[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:01.631011  6748 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.151.62:40397
I20260812 06:19:01.632100  6748 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:01.632735  6748 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:01.639055  6754 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:01.639128  6755 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:19:01.639081  6757 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:01.639755  6748 server_base.cc:1061] running on GCE node
I20260812 06:19:01.640383  6748 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:01.640508  6748 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:01.640555  6748 hybrid_clock.cc:648] HybridClock initialized: now 1786515541640553 us; error 0 us; skew 500 ppm
I20260812 06:19:01.642364  6748 webserver.cc:533] Webserver started at http://127.6.151.62:35541/ using document root <none> and password file <none>
I20260812 06:19:01.642932  6748 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:01.642992  6748 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:01.643266  6748 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:01.644971  6748 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/master-0-root/instance:
uuid: "4f8a5c6fcf8d4466847ec040cb534200"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-1jjb"
I20260812 06:19:01.648442  6748 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:19:01.650409  6764 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:01.651346  6748 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:01.651479  6748 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/master-0-root
uuid: "4f8a5c6fcf8d4466847ec040cb534200"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-1jjb"
I20260812 06:19:01.651593  6748 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:01.685810  6748 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:01.686527  6748 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:01.686719  6748 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:01.694478  6748 rpc_server.cc:307] RPC server started. Bound to: 127.6.151.62:40397
I20260812 06:19:01.694496  6822 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.151.62:40397 every 8 connection(s)
I20260812 06:19:01.696818  6823 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:01.702158  6823 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200: Bootstrap starting.
I20260812 06:19:01.704509  6823 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:01.705338  6823 log.cc:826] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:01.707027  6823 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200: No bootstrap required, opened a new log
I20260812 06:19:01.709872  6823 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f8a5c6fcf8d4466847ec040cb534200" member_type: VOTER }
I20260812 06:19:01.710036  6823 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:01.710088  6823 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4f8a5c6fcf8d4466847ec040cb534200, State: Initialized, Role: FOLLOWER
I20260812 06:19:01.710620  6823 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [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: "4f8a5c6fcf8d4466847ec040cb534200" member_type: VOTER }
I20260812 06:19:01.710753  6823 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:01.710798  6823 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:01.710886  6823 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:01.711621  6823 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f8a5c6fcf8d4466847ec040cb534200" member_type: VOTER }
I20260812 06:19:01.711997  6823 leader_election.cc:304] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [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: 4f8a5c6fcf8d4466847ec040cb534200; no voters: 
I20260812 06:19:01.712363  6823 leader_election.cc:290] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:01.712532  6826 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:01.712836  6826 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [term 1 LEADER]: Becoming Leader. State: Replica: 4f8a5c6fcf8d4466847ec040cb534200, State: Running, Role: LEADER
I20260812 06:19:01.713230  6826 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [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: "4f8a5c6fcf8d4466847ec040cb534200" member_type: VOTER }
I20260812 06:19:01.713428  6823 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:01.715699  6748 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:01.715651  6827 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4f8a5c6fcf8d4466847ec040cb534200" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f8a5c6fcf8d4466847ec040cb534200" member_type: VOTER } }
I20260812 06:19:01.715787  6827 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:01.715651  6828 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4f8a5c6fcf8d4466847ec040cb534200. Latest consensus state: current_term: 1 leader_uuid: "4f8a5c6fcf8d4466847ec040cb534200" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f8a5c6fcf8d4466847ec040cb534200" member_type: VOTER } }
I20260812 06:19:01.716035  6828 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [sys.catalog]: This master's current role is: LEADER
W20260812 06:19:01.717744  6840 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:01.717829  6840 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:01.717917  6841 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:01.718634  6841 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:01.723519  6841 catalog_manager.cc:1383] Generated new cluster ID: 02c6d9c7d2e94a10b6a9562e7f6797a8
I20260812 06:19:01.723585  6841 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:01.730810  6841 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:01.732151  6841 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:01.739512  6841 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200: Generated new TSK 0
I20260812 06:19:01.740361  6841 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:01.748363  6748 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:01.751052  6845 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:01.751060  6847 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:01.751238  6748 server_base.cc:1061] running on GCE node
W20260812 06:19:01.751425  6849 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:01.751662  6748 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:01.751705  6748 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:01.751721  6748 hybrid_clock.cc:648] HybridClock initialized: now 1786515541751721 us; error 0 us; skew 500 ppm
I20260812 06:19:01.752765  6748 webserver.cc:533] Webserver started at http://127.6.151.1:34591/ using document root <none> and password file <none>
I20260812 06:19:01.752941  6748 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:01.752993  6748 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:01.753103  6748 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:01.753513  6748 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/instance:
uuid: "2996300cd1bd4c4fadcd2ca708936c66"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-1jjb"
I20260812 06:19:01.755102  6748 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:01.756174  6856 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:01.756433  6748 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:01.756536  6748 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root
uuid: "2996300cd1bd4c4fadcd2ca708936c66"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-1jjb"
I20260812 06:19:01.756610  6748 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:01.772727  6748 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:01.773597  6748 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:01.774068  6748 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:01.774997  6748 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:01.775072  6748 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:01.775149  6748 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:01.775197  6748 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:01.781309  6748 rpc_server.cc:307] RPC server started. Bound to: 127.6.151.1:39295
I20260812 06:19:01.781384  6925 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.151.1:39295 every 8 connection(s)
I20260812 06:19:01.799691  6926 heartbeater.cc:344] Connected to a master server at 127.6.151.62:40397
I20260812 06:19:01.799961  6926 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:01.800475  6926 heartbeater.cc:507] Master 127.6.151.62:40397 requested a full tablet report, sending...
I20260812 06:19:01.801875  6781 ts_manager.cc:194] Registered new tserver with Master: 2996300cd1bd4c4fadcd2ca708936c66 (127.6.151.1:39295)
I20260812 06:19:01.801975  6748 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.020012484s
I20260812 06:19:01.803141  6781 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43768
I20260812 06:19:01.812026  6781 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43774:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:01.826962  6884 tablet_service.cc:1511] Processing CreateTablet for tablet 356c0486048e422d9d01044c7174504b (DEFAULT_TABLE table=heavy-update-compaction-test [id=6e897a4c60594e9292a9668e4afa35ae]), partition=
I20260812 06:19:01.827473  6884 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 356c0486048e422d9d01044c7174504b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:01.830468  6940 tablet_bootstrap.cc:492] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Bootstrap starting.
I20260812 06:19:01.831375  6940 tablet_bootstrap.cc:654] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:01.832525  6940 tablet_bootstrap.cc:492] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: No bootstrap required, opened a new log
I20260812 06:19:01.832654  6940 ts_tablet_manager.cc:1403] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:01.833036  6940 raft_consensus.cc:359] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2996300cd1bd4c4fadcd2ca708936c66" member_type: VOTER last_known_addr { host: "127.6.151.1" port: 39295 } }
I20260812 06:19:01.833153  6940 raft_consensus.cc:385] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:01.833232  6940 raft_consensus.cc:740] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2996300cd1bd4c4fadcd2ca708936c66, State: Initialized, Role: FOLLOWER
I20260812 06:19:01.833521  6940 consensus_queue.cc:260] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [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: "2996300cd1bd4c4fadcd2ca708936c66" member_type: VOTER last_known_addr { host: "127.6.151.1" port: 39295 } }
I20260812 06:19:01.833664  6940 raft_consensus.cc:399] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:01.833750  6940 raft_consensus.cc:493] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:01.833811  6940 raft_consensus.cc:3060] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:01.834584  6940 raft_consensus.cc:515] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2996300cd1bd4c4fadcd2ca708936c66" member_type: VOTER last_known_addr { host: "127.6.151.1" port: 39295 } }
I20260812 06:19:01.834738  6940 leader_election.cc:304] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [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: 2996300cd1bd4c4fadcd2ca708936c66; no voters: 
I20260812 06:19:01.834949  6940 leader_election.cc:290] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:01.835071  6942 raft_consensus.cc:2804] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:01.835282  6940 ts_tablet_manager.cc:1434] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:01.835368  6942 raft_consensus.cc:697] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [term 1 LEADER]: Becoming Leader. State: Replica: 2996300cd1bd4c4fadcd2ca708936c66, State: Running, Role: LEADER
I20260812 06:19:01.835505  6926 heartbeater.cc:499] Master 127.6.151.62:40397 was elected leader, sending a full tablet report...
I20260812 06:19:01.835542  6942 consensus_queue.cc:237] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [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: "2996300cd1bd4c4fadcd2ca708936c66" member_type: VOTER last_known_addr { host: "127.6.151.1" port: 39295 } }
I20260812 06:19:01.838420  6781 catalog_manager.cc:5719] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 reported cstate change: term changed from 0 to 1, leader changed from <none> to 2996300cd1bd4c4fadcd2ca708936c66 (127.6.151.1). New cstate: current_term: 1 leader_uuid: "2996300cd1bd4c4fadcd2ca708936c66" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2996300cd1bd4c4fadcd2ca708936c66" member_type: VOTER last_known_addr { host: "127.6.151.1" port: 39295 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:01.905009  6748 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.023s	sys 0.004s
I20260812 06:19:02.032513  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushMRSOp(356c0486048e422d9d01044c7174504b): perf score=15.086190
I20260812 06:19:02.203819  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushMRSOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.171s	user 0.116s	sys 0.048s Metrics: {"bytes_written":13661286,"cfile_init":1,"compiler_manager_pool.queue_time_us":198,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":860,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43001,"lbm_writes_lt_1ms":700,"mutex_wait_us":995,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":166144,"thread_start_us":126,"threads_started":1,"update_count":1665}
I20260812 06:19:02.205207  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:02.219753  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3446263,"delete_count":0,"lbm_write_time_us":5439,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:19:02.220268  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling LogGCOp(356c0486048e422d9d01044c7174504b): free 20743880 bytes of WAL
I20260812 06:19:02.220662  6861 log_reader.cc:385] T 356c0486048e422d9d01044c7174504b: removed 2 log segments from log reader
I20260812 06:19:02.220786  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000001 (ops 1-6)
I20260812 06:19:02.220901  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000002 (ops 7-11)
I20260812 06:19:02.227126  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: LogGCOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.007s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:02.227511  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling UndoDeltaBlockGCOp(356c0486048e422d9d01044c7174504b): 12719216 bytes on disk
I20260812 06:19:02.228212  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: UndoDeltaBlockGCOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:19:02.228675  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=1.196750
I20260812 06:19:02.240949  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":4568,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:19:02.241479  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:02.409667  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.168s	user 0.120s	sys 0.045s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364529,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":609,"lbm_read_time_us":12926,"lbm_reads_lt_1ms":559,"lbm_write_time_us":28960,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":338,"threads_started":5,"update_count":2450}
I20260812 06:19:02.412398  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=10.126437
I20260812 06:19:02.453945  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.041s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17650,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.454672  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:02.470283  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5373,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.470861  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:02.596511  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.125s	user 0.097s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":606,"lbm_read_time_us":9038,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24227,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:19:02.597277  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=10.126437
I20260812 06:19:02.637054  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.040s	user 0.016s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15076,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.637606  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:02.653294  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.653837  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:02.778461  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.124s	user 0.099s	sys 0.025s 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":932,"lbm_read_time_us":10187,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23019,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:19:02.779218  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=10.126437
I20260812 06:19:02.820984  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.042s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14363,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.821532  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:02.832438  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4276,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.832877  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:02.978726  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.146s	user 0.097s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":434,"lbm_read_time_us":11691,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23760,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:19:02.979403  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=10.126437
I20260812 06:19:03.017462  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.038s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15088,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.018112  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:03.030452  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4173,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.031105  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:03.156606  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.125s	user 0.112s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2544,"lbm_read_time_us":9411,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23428,"lbm_writes_lt_1ms":443,"mutex_wait_us":1212,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:19:03.157543  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=10.126437
I20260812 06:19:03.199980  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.042s	user 0.012s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15703,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.200486  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:03.211437  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4378,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.212204  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:03.345326  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.133s	user 0.103s	sys 0.029s 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":244,"lbm_read_time_us":11083,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23859,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2000}
I20260812 06:19:03.345994  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=10.126437
I20260812 06:19:03.398545  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.052s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16426,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.399119  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:03.410167  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4370,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.410594  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushMRSOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:03.455821  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushMRSOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.045s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1564,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1841,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:03.456720  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling LogGCOp(356c0486048e422d9d01044c7174504b): free 112239279 bytes of WAL
I20260812 06:19:03.457000  6861 log_reader.cc:385] T 356c0486048e422d9d01044c7174504b: removed 11 log segments from log reader
I20260812 06:19:03.457065  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000003 (ops 12-16)
I20260812 06:19:03.457106  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000004 (ops 17-20)
I20260812 06:19:03.457182  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000005 (ops 21-25)
I20260812 06:19:03.457206  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000006 (ops 26-30)
I20260812 06:19:03.457227  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000007 (ops 31-35)
I20260812 06:19:03.457259  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000008 (ops 36-40)
I20260812 06:19:03.457284  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000009 (ops 41-45)
I20260812 06:19:03.457306  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000010 (ops 46-50)
I20260812 06:19:03.457327  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000011 (ops 51-55)
I20260812 06:19:03.457348  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000012 (ops 56-60)
I20260812 06:19:03.457370  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000013 (ops 61-65)
I20260812 06:19:03.488590  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: LogGCOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:19:03.489023  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:03.515959  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.027s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5394,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.516484  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling UndoDeltaBlockGCOp(356c0486048e422d9d01044c7174504b): 447 bytes on disk
I20260812 06:19:03.516868  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: UndoDeltaBlockGCOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.517266  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:03.527812  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.528311  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:03.732344  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.204s	user 0.163s	sys 0.041s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877337,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":255,"lbm_read_time_us":14638,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34765,"lbm_writes_lt_1ms":643,"mutex_wait_us":112,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:19:03.732888  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=14.095187
I20260812 06:19:03.789498  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.056s	user 0.047s	sys 0.004s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24150,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.789971  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:03.954890  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.165s	user 0.101s	sys 0.060s 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":218,"lbm_read_time_us":10842,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26398,"lbm_writes_lt_1ms":443,"mutex_wait_us":96,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:19:03.955951  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=11.118625
I20260812 06:19:03.992447  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.036s	user 0.013s	sys 0.023s Metrics: {"bytes_written":12676713,"delete_count":0,"lbm_write_time_us":16027,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1545}
I20260812 06:19:03.993409  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:04.008677  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.015s	user 0.002s	sys 0.012s Metrics: {"bytes_written":3733433,"delete_count":0,"lbm_write_time_us":5490,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:19:04.009225  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:04.154430  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.145s	user 0.120s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672274,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":173,"lbm_read_time_us":10196,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26925,"lbm_writes_lt_1ms":443,"mutex_wait_us":90,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2000}
I20260812 06:19:04.155222  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=11.118625
I20260812 06:19:04.187644  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.032s	user 0.022s	sys 0.007s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14202,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:04.188417  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:04.200996  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4757,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.201907  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:04.331959  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.130s	user 0.101s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":298,"lbm_read_time_us":8765,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24984,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2000}
I20260812 06:19:04.333218  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=10.126437
I20260812 06:19:04.374063  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.041s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17576,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.374624  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:04.390250  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5731,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.390852  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:04.516714  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.126s	user 0.106s	sys 0.019s 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":193,"lbm_read_time_us":9520,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23841,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:19:04.517480  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=10.126437
I20260812 06:19:04.566532  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.049s	user 0.035s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17212,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.567178  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:04.579494  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4817,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.580288  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:04.729929  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.149s	user 0.100s	sys 0.049s 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":567,"lbm_read_time_us":12315,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26498,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:19:04.730638  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=11.118625
I20260812 06:19:04.768620  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.038s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17448,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:04.769410  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:04.782775  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4739,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.783231  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:04.905761  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.122s	user 0.103s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":871,"lbm_read_time_us":7926,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23895,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:19:04.906478  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=11.118625
I20260812 06:19:04.943001  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.036s	user 0.028s	sys 0.005s Metrics: {"bytes_written":12717739,"delete_count":0,"lbm_write_time_us":15177,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":1550}
I20260812 06:19:04.943810  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:04.959076  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5267,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.959610  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushMRSOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:04.999284  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushMRSOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.040s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1486,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2068,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:05.000168  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=3.181125
I20260812 06:19:05.013628  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4746,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:05.014071  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling LogGCOp(356c0486048e422d9d01044c7174504b): free 128414447 bytes of WAL
I20260812 06:19:05.014289  6861 log_reader.cc:385] T 356c0486048e422d9d01044c7174504b: removed 13 log segments from log reader
I20260812 06:19:05.014349  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000014 (ops 66-70)
I20260812 06:19:05.014401  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000015 (ops 71-75)
I20260812 06:19:05.014458  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000016 (ops 76-80)
I20260812 06:19:05.014498  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000017 (ops 81-84)
I20260812 06:19:05.014544  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000018 (ops 85-89)
I20260812 06:19:05.014587  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000019 (ops 90-94)
I20260812 06:19:05.014623  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000020 (ops 95-98)
I20260812 06:19:05.014659  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000021 (ops 99-103)
I20260812 06:19:05.014696  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000022 (ops 104-108)
I20260812 06:19:05.014781  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000023 (ops 109-112)
I20260812 06:19:05.014819  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000024 (ops 113-117)
I20260812 06:19:05.014858  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000025 (ops 118-122)
I20260812 06:19:05.014894  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000026 (ops 123-126)
I20260812 06:19:05.043924  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: LogGCOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:05.044365  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling UndoDeltaBlockGCOp(356c0486048e422d9d01044c7174504b): 483 bytes on disk
I20260812 06:19:05.044787  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: UndoDeltaBlockGCOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:05.045321  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:05.056636  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4139,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.057099  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:05.066864  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3734,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:05.067284  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:05.271173  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.204s	user 0.130s	sys 0.068s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979852,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":177,"lbm_read_time_us":16341,"lbm_reads_lt_1ms":775,"lbm_write_time_us":39888,"lbm_writes_lt_1ms":743,"mutex_wait_us":68,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16640,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:19:05.271898  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=14.095187
I20260812 06:19:05.320762  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.049s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19096,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.321380  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:05.334108  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.335067  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:05.529966  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.195s	user 0.145s	sys 0.043s 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":147,"lbm_read_time_us":12294,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31911,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2500}
I20260812 06:19:05.530802  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=14.095187
I20260812 06:19:05.588640  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.058s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21830,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.589172  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:05.605036  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.605829  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:05.764235  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.158s	user 0.102s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1273,"lbm_read_time_us":12263,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31321,"lbm_writes_lt_1ms":543,"mutex_wait_us":495,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2500}
I20260812 06:19:05.764912  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=10.126437
I20260812 06:19:05.801471  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.036s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14724,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:19:05.802107  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:05.826576  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.024s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6707,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.827097  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:05.837991  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.838486  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:05.995252  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.155s	user 0.119s	sys 0.033s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774806,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":750,"lbm_read_time_us":9331,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33260,"lbm_writes_lt_1ms":543,"mutex_wait_us":310,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:19:05.995980  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=11.118625
I20260812 06:19:06.044392  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.048s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":19338,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:06.045068  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:06.056119  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4016,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.056541  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:06.066108  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3743,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.066572  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:06.214226  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.147s	user 0.123s	sys 0.024s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":242,"lbm_read_time_us":11129,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28957,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2500}
I20260812 06:19:06.214830  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=11.118625
I20260812 06:19:06.257170  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.042s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18265,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:06.257817  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:06.276154  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.018s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5448,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.276744  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:06.410444  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.133s	user 0.088s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":55,"lbm_read_time_us":8314,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25392,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:19:06.411242  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=11.118625
I20260812 06:19:06.459164  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.047s	user 0.027s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21344,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:06.459861  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:06.485361  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.025s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.485944  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:06.496686  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4025,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.497257  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushMRSOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:06.534477  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushMRSOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.037s	user 0.030s	sys 0.003s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1521,"drs_written":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1671,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:06.535247  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling LogGCOp(356c0486048e422d9d01044c7174504b): free 129320714 bytes of WAL
I20260812 06:19:06.535564  6861 log_reader.cc:385] T 356c0486048e422d9d01044c7174504b: removed 13 log segments from log reader
I20260812 06:19:06.535615  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000027 (ops 127-131)
I20260812 06:19:06.535648  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000028 (ops 132-136)
I20260812 06:19:06.535722  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000029 (ops 137-141)
I20260812 06:19:06.535774  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000030 (ops 142-146)
I20260812 06:19:06.535827  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000031 (ops 147-151)
I20260812 06:19:06.535871  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000032 (ops 152-156)
I20260812 06:19:06.535916  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000033 (ops 157-160)
I20260812 06:19:06.535984  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000034 (ops 161-165)
I20260812 06:19:06.536031  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000035 (ops 166-170)
I20260812 06:19:06.536108  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000036 (ops 171-174)
I20260812 06:19:06.536154  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000037 (ops 175-179)
I20260812 06:19:06.536201  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000038 (ops 180-184)
I20260812 06:19:06.536247  6861 log.cc:1079] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/356c0486048e422d9d01044c7174504b/wal-000000039 (ops 185-189)
I20260812 06:19:06.566283  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: LogGCOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.031s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:19:06.566867  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling UndoDeltaBlockGCOp(356c0486048e422d9d01044c7174504b): 482 bytes on disk
I20260812 06:19:06.567446  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: UndoDeltaBlockGCOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:19:06.567991  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=3.181125
I20260812 06:19:06.580670  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4581,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:06.581156  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=2.188937
I20260812 06:19:06.594527  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5076,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.595050  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:06.793546  6748 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.888s	user 1.838s	sys 0.125s
I20260812 06:19:06.805222  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.210s	user 0.152s	sys 0.057s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979848,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":16274,"lbm_reads_lt_1ms":771,"lbm_write_time_us":39319,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":3500}
I20260812 06:19:06.805824  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b): perf score=14.095187
I20260812 06:19:06.838707  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: FlushDeltaMemStoresOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.033s	user 0.031s	sys 0.001s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15604,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:06.839346  6927 maintenance_manager.cc:419] P 2996300cd1bd4c4fadcd2ca708936c66: Scheduling MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b): perf score=1.000000
I20260812 06:19:06.876670  6748 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.082s	user 0.004s	sys 0.000s
I20260812 06:19:06.877315  6748 tablet_server.cc:179] TabletServer@127.6.151.1:0 shutting down...
I20260812 06:19:06.968035  6861 maintenance_manager.cc:643] P 2996300cd1bd4c4fadcd2ca708936c66: MajorDeltaCompactionOp(356c0486048e422d9d01044c7174504b) complete. Timing: real 0.128s	user 0.098s	sys 0.028s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":3544,"lbm_read_time_us":10107,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27030,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":2797,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.968827  6748 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:06.969269  6748 tablet_replica.cc:333] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66: stopping tablet replica
I20260812 06:19:06.969519  6748 raft_consensus.cc:2243] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:06.969772  6748 raft_consensus.cc:2272] T 356c0486048e422d9d01044c7174504b P 2996300cd1bd4c4fadcd2ca708936c66 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:06.985028  6748 tablet_server.cc:196] TabletServer@127.6.151.1:0 shutdown complete.
I20260812 06:19:07.005064  6748 master.cc:562] Master@127.6.151.62:40397 shutting down...
I20260812 06:19:07.009086  6748 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.009259  6748 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.009317  6748 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4f8a5c6fcf8d4466847ec040cb534200: stopping tablet replica
I20260812 06:19:07.021641  6748 master.cc:584] Master@127.6.151.62:40397 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5484 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:07.129432  6748 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.151.62:33235
I20260812 06:19:07.129881  6748 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:07.132434  6961 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:07.132450  6964 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:07.132519  6962 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:07.132591  6748 server_base.cc:1061] running on GCE node
I20260812 06:19:07.132923  6748 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:07.132961  6748 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:07.132977  6748 hybrid_clock.cc:648] HybridClock initialized: now 1786515547132977 us; error 0 us; skew 500 ppm
I20260812 06:19:07.133765  6748 webserver.cc:533] Webserver started at http://127.6.151.62:40187/ using document root <none> and password file <none>
I20260812 06:19:07.133903  6748 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:07.133950  6748 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:07.134020  6748 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:07.134375  6748 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/master-0-root/instance:
uuid: "5e1d991b5ae44db1a4bf96690b6e990a"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-1jjb"
I20260812 06:19:07.135931  6748 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:19:07.137019  6969 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.137262  6748 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:07.137331  6748 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/master-0-root
uuid: "5e1d991b5ae44db1a4bf96690b6e990a"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-1jjb"
I20260812 06:19:07.137435  6748 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:07.146962  6748 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:07.147403  6748 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:07.151815  6748 rpc_server.cc:307] RPC server started. Bound to: 127.6.151.62:33235
I20260812 06:19:07.159368  7032 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.151.62:33235 every 8 connection(s)
I20260812 06:19:07.159878  7033 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:07.161738  7033 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a: Bootstrap starting.
I20260812 06:19:07.162521  7033 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:07.163614  7033 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a: No bootstrap required, opened a new log
I20260812 06:19:07.164028  7033 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e1d991b5ae44db1a4bf96690b6e990a" member_type: VOTER }
I20260812 06:19:07.164158  7033 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:07.164211  7033 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5e1d991b5ae44db1a4bf96690b6e990a, State: Initialized, Role: FOLLOWER
I20260812 06:19:07.164373  7033 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [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: "5e1d991b5ae44db1a4bf96690b6e990a" member_type: VOTER }
I20260812 06:19:07.164464  7033 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:07.164512  7033 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:07.164572  7033 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:07.165241  7033 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e1d991b5ae44db1a4bf96690b6e990a" member_type: VOTER }
I20260812 06:19:07.165391  7033 leader_election.cc:304] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [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: 5e1d991b5ae44db1a4bf96690b6e990a; no voters: 
I20260812 06:19:07.165598  7033 leader_election.cc:290] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:07.165769  7036 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:07.166033  7036 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [term 1 LEADER]: Becoming Leader. State: Replica: 5e1d991b5ae44db1a4bf96690b6e990a, State: Running, Role: LEADER
I20260812 06:19:07.166107  7033 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:07.166214  7036 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [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: "5e1d991b5ae44db1a4bf96690b6e990a" member_type: VOTER }
I20260812 06:19:07.166708  7037 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5e1d991b5ae44db1a4bf96690b6e990a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e1d991b5ae44db1a4bf96690b6e990a" member_type: VOTER } }
I20260812 06:19:07.166838  7037 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:07.166935  7038 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5e1d991b5ae44db1a4bf96690b6e990a. Latest consensus state: current_term: 1 leader_uuid: "5e1d991b5ae44db1a4bf96690b6e990a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5e1d991b5ae44db1a4bf96690b6e990a" member_type: VOTER } }
I20260812 06:19:07.167025  7038 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:07.167524  7043 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:07.168506  7043 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:07.168702  6748 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:07.170460  7043 catalog_manager.cc:1383] Generated new cluster ID: 41d4c75bafe448908ad7d89c16761b8f
I20260812 06:19:07.170528  7043 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:07.178835  7043 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:07.179379  7043 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:07.191306  7043 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a: Generated new TSK 0
I20260812 06:19:07.191535  7043 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:07.201146  6748 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:07.203447  7058 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:19:07.203529  7060 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:07.203672  6748 server_base.cc:1061] running on GCE node
W20260812 06:19:07.203459  7057 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:19:07.203986  6748 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:07.204104  6748 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:07.204129  6748 hybrid_clock.cc:648] HybridClock initialized: now 1786515547204129 us; error 0 us; skew 500 ppm
I20260812 06:19:07.205057  6748 webserver.cc:533] Webserver started at http://127.6.151.1:33601/ using document root <none> and password file <none>
I20260812 06:19:07.205252  6748 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:07.205322  6748 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:07.205403  6748 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:07.205822  6748 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/instance:
uuid: "53c78836d2274b6a882da830710d11d2"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-1jjb"
I20260812 06:19:07.207365  6748 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:07.208437  7065 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.208815  6748 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:07.208906  6748 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root
uuid: "53c78836d2274b6a882da830710d11d2"
format_stamp: "Formatted at 2026-08-12 06:19:07 on dist-test-slave-1jjb"
I20260812 06:19:07.208997  6748 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:07.218650  6748 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:07.219105  6748 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:07.219424  6748 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:07.219901  6748 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:07.219962  6748 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.220031  6748 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:07.220116  6748 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:07.224502  6748 rpc_server.cc:307] RPC server started. Bound to: 127.6.151.1:37059
I20260812 06:19:07.224575  7137 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.151.1:37059 every 8 connection(s)
I20260812 06:19:07.233196  7138 heartbeater.cc:344] Connected to a master server at 127.6.151.62:33235
I20260812 06:19:07.233312  7138 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:07.233525  7138 heartbeater.cc:507] Master 127.6.151.62:33235 requested a full tablet report, sending...
I20260812 06:19:07.234138  6991 ts_manager.cc:194] Registered new tserver with Master: 53c78836d2274b6a882da830710d11d2 (127.6.151.1:37059)
I20260812 06:19:07.234871  6991 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53190
I20260812 06:19:07.234897  6748 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009925316s
I20260812 06:19:07.242244  6991 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53192:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:07.251329  7097 tablet_service.cc:1511] Processing CreateTablet for tablet 8f33d4334d9e4d83b6b0cff5e695a294 (DEFAULT_TABLE table=heavy-update-compaction-test [id=87b38980e85a4bacb0587ebde4eef47a]), partition=
I20260812 06:19:07.251645  7097 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8f33d4334d9e4d83b6b0cff5e695a294. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:07.253784  7151 tablet_bootstrap.cc:492] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Bootstrap starting.
I20260812 06:19:07.254688  7151 tablet_bootstrap.cc:654] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:07.255759  7151 tablet_bootstrap.cc:492] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: No bootstrap required, opened a new log
I20260812 06:19:07.255831  7151 ts_tablet_manager.cc:1403] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:07.256464  7151 raft_consensus.cc:359] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "53c78836d2274b6a882da830710d11d2" member_type: VOTER last_known_addr { host: "127.6.151.1" port: 37059 } }
I20260812 06:19:07.256551  7151 raft_consensus.cc:385] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:07.256608  7151 raft_consensus.cc:740] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 53c78836d2274b6a882da830710d11d2, State: Initialized, Role: FOLLOWER
I20260812 06:19:07.256757  7151 consensus_queue.cc:260] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [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: "53c78836d2274b6a882da830710d11d2" member_type: VOTER last_known_addr { host: "127.6.151.1" port: 37059 } }
I20260812 06:19:07.256877  7151 raft_consensus.cc:399] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:07.256969  7151 raft_consensus.cc:493] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:07.257035  7151 raft_consensus.cc:3060] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:07.257753  7151 raft_consensus.cc:515] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "53c78836d2274b6a882da830710d11d2" member_type: VOTER last_known_addr { host: "127.6.151.1" port: 37059 } }
I20260812 06:19:07.257903  7151 leader_election.cc:304] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [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: 53c78836d2274b6a882da830710d11d2; no voters: 
I20260812 06:19:07.258136  7151 leader_election.cc:290] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:07.258263  7153 raft_consensus.cc:2804] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:07.258461  7151 ts_tablet_manager.cc:1434] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:07.258486  7138 heartbeater.cc:499] Master 127.6.151.62:33235 was elected leader, sending a full tablet report...
I20260812 06:19:07.258562  7153 raft_consensus.cc:697] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [term 1 LEADER]: Becoming Leader. State: Replica: 53c78836d2274b6a882da830710d11d2, State: Running, Role: LEADER
I20260812 06:19:07.258697  7153 consensus_queue.cc:237] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [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: "53c78836d2274b6a882da830710d11d2" member_type: VOTER last_known_addr { host: "127.6.151.1" port: 37059 } }
I20260812 06:19:07.260177  6991 catalog_manager.cc:5719] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 reported cstate change: term changed from 0 to 1, leader changed from <none> to 53c78836d2274b6a882da830710d11d2 (127.6.151.1). New cstate: current_term: 1 leader_uuid: "53c78836d2274b6a882da830710d11d2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "53c78836d2274b6a882da830710d11d2" member_type: VOTER last_known_addr { host: "127.6.151.1" port: 37059 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:07.320649  6748 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.012s	sys 0.011s
I20260812 06:19:07.475553  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushMRSOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=19.054940
I20260812 06:19:07.641729  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushMRSOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.166s	user 0.132s	sys 0.031s Metrics: {"bytes_written":12922854,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":806,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40008,"lbm_writes_lt_1ms":772,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":15104,"update_count":1575}
I20260812 06:19:07.642851  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling LogGCOp(8f33d4334d9e4d83b6b0cff5e695a294): free 20743831 bytes of WAL
I20260812 06:19:07.643149  7071 log_reader.cc:385] T 8f33d4334d9e4d83b6b0cff5e695a294: removed 2 log segments from log reader
I20260812 06:19:07.643220  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000001 (ops 1-6)
I20260812 06:19:07.643285  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000002 (ops 7-11)
I20260812 06:19:07.649140  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: LogGCOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:19:07.649521  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling UndoDeltaBlockGCOp(8f33d4334d9e4d83b6b0cff5e695a294): 16411394 bytes on disk
I20260812 06:19:07.650110  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: UndoDeltaBlockGCOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:19:07.650575  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:07.671123  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.020s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3897537,"delete_count":0,"lbm_write_time_us":6065,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:19:07.671528  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:07.681056  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3656,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.681509  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:07.881947  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.200s	user 0.120s	sys 0.075s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774796,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":575,"lbm_read_time_us":14212,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31331,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":337,"threads_started":5,"update_count":2500}
I20260812 06:19:07.882709  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=14.095187
I20260812 06:19:07.942792  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.060s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25878,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.943315  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:08.099716  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.156s	user 0.120s	sys 0.036s 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":201,"lbm_read_time_us":11491,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25998,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":2000}
I20260812 06:19:08.100414  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=14.095187
I20260812 06:19:08.153555  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.053s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20925,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.154054  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:08.170075  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6171,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.170830  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:08.378073  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.207s	user 0.128s	sys 0.072s 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":1195,"lbm_read_time_us":13031,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29993,"lbm_writes_lt_1ms":543,"mutex_wait_us":355,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:08.378782  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=14.095187
I20260812 06:19:08.431249  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.052s	user 0.040s	sys 0.005s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21292,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.431773  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:08.446122  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5212,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.446662  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:08.618263  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.171s	user 0.124s	sys 0.038s 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":274,"lbm_read_time_us":10834,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32453,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:19:08.618993  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=11.118625
I20260812 06:19:08.649987  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.031s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13788,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:08.650765  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:08.667914  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5829,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.668403  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:08.800168  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.132s	user 0.108s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":395,"lbm_read_time_us":7919,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27838,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:19:08.800916  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=10.126437
I20260812 06:19:08.843945  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.043s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17808,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:08.844460  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:08.855222  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.855726  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:08.988356  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.132s	user 0.092s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":717,"lbm_read_time_us":9669,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26379,"lbm_writes_lt_1ms":443,"mutex_wait_us":348,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:19:08.988932  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=10.126437
I20260812 06:19:09.044315  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.055s	user 0.020s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15249,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.044862  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:09.055378  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4184,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.055830  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushMRSOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:09.099115  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushMRSOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.043s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":97,"dirs.run_cpu_time_us":202,"dirs.run_wall_time_us":1256,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1537,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:09.099846  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling LogGCOp(8f33d4334d9e4d83b6b0cff5e695a294): free 124710301 bytes of WAL
I20260812 06:19:09.100174  7071 log_reader.cc:385] T 8f33d4334d9e4d83b6b0cff5e695a294: removed 12 log segments from log reader
I20260812 06:19:09.100245  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000003 (ops 12-16)
I20260812 06:19:09.100291  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000004 (ops 17-21)
I20260812 06:19:09.100323  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000005 (ops 22-26)
I20260812 06:19:09.100353  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000006 (ops 27-31)
I20260812 06:19:09.100381  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000007 (ops 32-36)
I20260812 06:19:09.100412  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000008 (ops 37-41)
I20260812 06:19:09.100446  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000009 (ops 42-46)
I20260812 06:19:09.100472  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000010 (ops 47-51)
I20260812 06:19:09.100495  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000011 (ops 52-56)
I20260812 06:19:09.100524  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000012 (ops 57-61)
I20260812 06:19:09.100553  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000013 (ops 62-66)
I20260812 06:19:09.100581  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000014 (ops 67-71)
I20260812 06:19:09.132732  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: LogGCOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.033s	user 0.001s	sys 0.031s Metrics: {}
I20260812 06:19:09.133102  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling UndoDeltaBlockGCOp(8f33d4334d9e4d83b6b0cff5e695a294): 482 bytes on disk
I20260812 06:19:09.133493  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: UndoDeltaBlockGCOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:09.133946  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=3.181125
I20260812 06:19:09.158531  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.024s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6537,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:09.158999  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:09.169996  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4074,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:09.171167  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:09.398550  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.227s	user 0.152s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":240,"lbm_read_time_us":16230,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35011,"lbm_writes_lt_1ms":643,"mutex_wait_us":81,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":102,"threads_started":1,"update_count":3000}
I20260812 06:19:09.399392  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=18.063937
I20260812 06:19:09.457185  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.057s	user 0.031s	sys 0.024s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":25239,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:09.457777  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:09.637531  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.180s	user 0.123s	sys 0.056s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774576,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":522,"lbm_read_time_us":13502,"lbm_reads_lt_1ms":563,"lbm_write_time_us":30334,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":35712,"update_count":2500}
I20260812 06:19:09.638094  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=14.095187
I20260812 06:19:09.699039  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.061s	user 0.026s	sys 0.030s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21685,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.699604  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:09.710315  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4149,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.710814  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:09.904342  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.193s	user 0.125s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":13151,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31805,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2500}
I20260812 06:19:09.905062  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=14.095187
I20260812 06:19:09.956130  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.051s	user 0.028s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20143,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.956709  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:09.984063  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.027s	user 0.002s	sys 0.022s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.984704  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:10.164729  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.180s	user 0.126s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":527,"lbm_read_time_us":13406,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29211,"lbm_writes_lt_1ms":543,"mutex_wait_us":136,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:10.165409  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=14.095187
I20260812 06:19:10.218076  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.053s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22130,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:10.218655  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:10.234426  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.235141  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:10.427088  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.192s	user 0.124s	sys 0.062s 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":537,"lbm_read_time_us":14229,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29629,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:19:10.427820  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=11.118625
I20260812 06:19:10.484311  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.056s	user 0.036s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":22285,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:10.484864  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=6.157687
I20260812 06:19:10.506995  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.022s	user 0.016s	sys 0.004s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":9096,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:10.507722  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:10.666488  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.159s	user 0.128s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":156,"lbm_read_time_us":10405,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29395,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:10.667376  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=11.118625
I20260812 06:19:10.707324  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.040s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17012,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:10.707931  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:10.723392  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4630,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:10.724064  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushMRSOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:10.777199  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushMRSOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.053s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1174,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1777,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:10.778023  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling LogGCOp(8f33d4334d9e4d83b6b0cff5e695a294): free 129320580 bytes of WAL
I20260812 06:19:10.778306  7071 log_reader.cc:385] T 8f33d4334d9e4d83b6b0cff5e695a294: removed 13 log segments from log reader
I20260812 06:19:10.778379  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000015 (ops 72-76)
I20260812 06:19:10.778421  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000016 (ops 77-80)
I20260812 06:19:10.778460  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000017 (ops 81-85)
I20260812 06:19:10.778492  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000018 (ops 86-90)
I20260812 06:19:10.778515  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000019 (ops 91-94)
I20260812 06:19:10.778537  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000020 (ops 95-99)
I20260812 06:19:10.778558  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000021 (ops 100-104)
I20260812 06:19:10.778580  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000022 (ops 105-109)
I20260812 06:19:10.778606  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000023 (ops 110-114)
I20260812 06:19:10.778631  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000024 (ops 115-119)
I20260812 06:19:10.778654  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000025 (ops 120-124)
I20260812 06:19:10.778683  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000026 (ops 125-129)
I20260812 06:19:10.778712  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000027 (ops 130-134)
I20260812 06:19:10.811555  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: LogGCOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:10.811964  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=7.149875
I20260812 06:19:10.844867  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.033s	user 0.012s	sys 0.020s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9236,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:10.845494  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling LogGCOp(8f33d4334d9e4d83b6b0cff5e695a294): free 11564893 bytes of WAL
I20260812 06:19:10.845731  7071 log_reader.cc:385] T 8f33d4334d9e4d83b6b0cff5e695a294: removed 1 log segments from log reader
I20260812 06:19:10.845775  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000028 (ops 135-138)
I20260812 06:19:10.848268  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: LogGCOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:10.848613  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:10.858767  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3910,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:10.859316  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling UndoDeltaBlockGCOp(8f33d4334d9e4d83b6b0cff5e695a294): 492 bytes on disk
I20260812 06:19:10.859951  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: UndoDeltaBlockGCOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":125,"lbm_reads_lt_1ms":4}
I20260812 06:19:10.860576  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:11.121066  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.260s	user 0.149s	sys 0.099s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979733,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3157,"lbm_read_time_us":16003,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41298,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":64640,"thread_start_us":114,"threads_started":1,"update_count":3500}
I20260812 06:19:11.121708  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=18.063937
I20260812 06:19:11.189870  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.068s	user 0.035s	sys 0.020s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25762,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:11.190390  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:11.203190  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.013s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4224,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.203694  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:11.401203  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.197s	user 0.137s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":222,"lbm_read_time_us":14092,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32700,"lbm_writes_lt_1ms":643,"mutex_wait_us":53,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":41088,"update_count":3000}
I20260812 06:19:11.401914  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=14.095187
I20260812 06:19:11.456367  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.053s	user 0.037s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23098,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.457334  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:11.472244  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5027,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.472924  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:11.649832  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.177s	user 0.127s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":12130,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29147,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:11.650913  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=15.087375
I20260812 06:19:11.704578  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.053s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":24156,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:11.705420  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:11.720316  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.015s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4519,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:11.720777  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:11.879184  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.158s	user 0.098s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":178,"lbm_read_time_us":11876,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27168,"lbm_writes_lt_1ms":543,"mutex_wait_us":83,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:19:11.882848  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=14.095187
I20260812 06:19:11.937270  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.054s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20219,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.937953  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:11.951231  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5009,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.951771  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:12.135722  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.184s	user 0.136s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1130,"lbm_read_time_us":13292,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28826,"lbm_writes_lt_1ms":543,"mutex_wait_us":235,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:19:12.136513  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=14.095187
I20260812 06:19:12.203967  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.067s	user 0.032s	sys 0.027s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23502,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.204649  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=2.188937
I20260812 06:19:12.216248  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4533,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.216784  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushMRSOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:12.247659  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushMRSOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.031s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":279,"dirs.run_wall_time_us":1227,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1734,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:12.248664  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=1.000000
I20260812 06:19:12.427194  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: MajorDeltaCompactionOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.178s	user 0.125s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":529,"lbm_read_time_us":12216,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30113,"lbm_writes_lt_1ms":543,"mutex_wait_us":287,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2500}
I20260812 06:19:12.427876  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling LogGCOp(8f33d4334d9e4d83b6b0cff5e695a294): free 112239552 bytes of WAL
I20260812 06:19:12.428190  7071 log_reader.cc:385] T 8f33d4334d9e4d83b6b0cff5e695a294: removed 11 log segments from log reader
I20260812 06:19:12.428288  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000029 (ops 139-143)
I20260812 06:19:12.428392  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000030 (ops 144-148)
I20260812 06:19:12.428474  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000031 (ops 149-153)
I20260812 06:19:12.428572  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000032 (ops 154-158)
I20260812 06:19:12.428678  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000033 (ops 159-163)
I20260812 06:19:12.428782  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000034 (ops 164-168)
I20260812 06:19:12.428865  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000035 (ops 169-172)
I20260812 06:19:12.428968  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000036 (ops 173-177)
I20260812 06:19:12.429081  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000037 (ops 178-182)
I20260812 06:19:12.429152  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000038 (ops 183-187)
I20260812 06:19:12.429224  7071 log.cc:1079] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: Deleting log segment in path: /tmp/dist-test-taskXMYuen/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515541620352-6748-0/minicluster-data/ts-0-root/wals/8f33d4334d9e4d83b6b0cff5e695a294/wal-000000039 (ops 188-192)
I20260812 06:19:12.458675  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: LogGCOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.031s	user 0.001s	sys 0.026s Metrics: {}
I20260812 06:19:12.459250  7139 maintenance_manager.cc:419] P 53c78836d2274b6a882da830710d11d2: Scheduling FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294): perf score=18.063937
I20260812 06:19:12.461081  6748 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.140s	user 1.892s	sys 0.185s
I20260812 06:19:12.488417  6748 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.027s	user 0.003s	sys 0.000s
I20260812 06:19:12.488950  6748 tablet_server.cc:179] TabletServer@127.6.151.1:0 shutting down...
I20260812 06:19:12.511201  7071 maintenance_manager.cc:643] P 53c78836d2274b6a882da830710d11d2: FlushDeltaMemStoresOp(8f33d4334d9e4d83b6b0cff5e695a294) complete. Timing: real 0.051s	user 0.037s	sys 0.010s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":22973,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:19:12.511839  6748 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:12.512089  6748 tablet_replica.cc:333] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2: stopping tablet replica
I20260812 06:19:12.512236  6748 raft_consensus.cc:2243] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:12.525496  6748 raft_consensus.cc:2272] T 8f33d4334d9e4d83b6b0cff5e695a294 P 53c78836d2274b6a882da830710d11d2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:12.529209  6748 tablet_server.cc:196] TabletServer@127.6.151.1:0 shutdown complete.
I20260812 06:19:12.531951  6748 master.cc:562] Master@127.6.151.62:33235 shutting down...
I20260812 06:19:12.535027  6748 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:12.535190  6748 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:12.535277  6748 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5e1d991b5ae44db1a4bf96690b6e990a: stopping tablet replica
I20260812 06:19:12.547719  6748 master.cc:584] Master@127.6.151.62:33235 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5524 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11010 ms total)

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