[==========] 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:17:32.709067 18540 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.27.62:45671
I20260812 06:17:32.710136 18540 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:17:32.710776 18540 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:32.717521 18553 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:17:32.717590 18540 server_base.cc:1061] running on GCE node
W20260812 06:17:32.717521 18555 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:17:32.717777 18548 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:32.718356 18540 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:32.718497 18540 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:32.718545 18540 hybrid_clock.cc:648] HybridClock initialized: now 1786515452718542 us; error 0 us; skew 500 ppm
I20260812 06:17:32.720557 18540 webserver.cc:533] Webserver started at http://127.18.27.62:33985/ using document root <none> and password file <none>
I20260812 06:17:32.721176 18540 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:32.721246 18540 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:32.721508 18540 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:32.723248 18540 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/master-0-root/instance:
uuid: "a4e6d0c6d1cd482f853274ec1aae1fc2"
format_stamp: "Formatted at 2026-08-12 06:17:32 on dist-test-slave-1l3l"
I20260812 06:17:32.727013 18540 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.003s
I20260812 06:17:32.729344 18562 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:32.730398 18540 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:32.730525 18540 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/master-0-root
uuid: "a4e6d0c6d1cd482f853274ec1aae1fc2"
format_stamp: "Formatted at 2026-08-12 06:17:32 on dist-test-slave-1l3l"
I20260812 06:17:32.730624 18540 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:32.752411 18540 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:32.753125 18540 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:17:32.753301 18540 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:32.761346 18540 rpc_server.cc:307] RPC server started. Bound to: 127.18.27.62:45671
I20260812 06:17:32.761343 18651 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.27.62:45671 every 8 connection(s)
I20260812 06:17:32.763787 18652 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:32.769590 18652 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2: Bootstrap starting.
I20260812 06:17:32.772101 18652 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:32.773082 18652 log.cc:826] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:32.774963 18652 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2: No bootstrap required, opened a new log
I20260812 06:17:32.778049 18652 raft_consensus.cc:359] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4e6d0c6d1cd482f853274ec1aae1fc2" member_type: VOTER }
I20260812 06:17:32.778240 18652 raft_consensus.cc:385] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:32.778306 18652 raft_consensus.cc:740] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a4e6d0c6d1cd482f853274ec1aae1fc2, State: Initialized, Role: FOLLOWER
I20260812 06:17:32.778998 18652 consensus_queue.cc:260] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [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: "a4e6d0c6d1cd482f853274ec1aae1fc2" member_type: VOTER }
I20260812 06:17:32.779158 18652 raft_consensus.cc:399] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:32.779232 18652 raft_consensus.cc:493] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:32.779366 18652 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:32.780308 18652 raft_consensus.cc:515] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4e6d0c6d1cd482f853274ec1aae1fc2" member_type: VOTER }
I20260812 06:17:32.780817 18652 leader_election.cc:304] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [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: a4e6d0c6d1cd482f853274ec1aae1fc2; no voters: 
I20260812 06:17:32.781198 18652 leader_election.cc:290] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:32.781353 18657 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:32.781574 18657 raft_consensus.cc:697] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [term 1 LEADER]: Becoming Leader. State: Replica: a4e6d0c6d1cd482f853274ec1aae1fc2, State: Running, Role: LEADER
I20260812 06:17:32.782038 18657 consensus_queue.cc:237] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [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: "a4e6d0c6d1cd482f853274ec1aae1fc2" member_type: VOTER }
I20260812 06:17:32.782231 18652 sys_catalog.cc:565] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:32.784060 18663 sys_catalog.cc:455] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a4e6d0c6d1cd482f853274ec1aae1fc2. Latest consensus state: current_term: 1 leader_uuid: "a4e6d0c6d1cd482f853274ec1aae1fc2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4e6d0c6d1cd482f853274ec1aae1fc2" member_type: VOTER } }
I20260812 06:17:32.784096 18661 sys_catalog.cc:455] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a4e6d0c6d1cd482f853274ec1aae1fc2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a4e6d0c6d1cd482f853274ec1aae1fc2" member_type: VOTER } }
I20260812 06:17:32.784194 18663 sys_catalog.cc:458] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:32.784197 18661 sys_catalog.cc:458] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:32.784543 18680 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:32.784564 18540 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:32.786952 18680 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:32.791688 18680 catalog_manager.cc:1383] Generated new cluster ID: 7fe1e558ecdc41e292978445c5063ad2
I20260812 06:17:32.791816 18680 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:32.803567 18680 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:32.804507 18680 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:32.818177 18680 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2: Generated new TSK 0
I20260812 06:17:32.818902 18680 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:32.849754 18540 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:32.853039 18690 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:32.853186 18694 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:17:32.853044 18689 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:32.853140 18540 server_base.cc:1061] running on GCE node
I20260812 06:17:32.853504 18540 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:32.853550 18540 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:32.853571 18540 hybrid_clock.cc:648] HybridClock initialized: now 1786515452853570 us; error 0 us; skew 500 ppm
I20260812 06:17:32.854480 18540 webserver.cc:533] Webserver started at http://127.18.27.1:35417/ using document root <none> and password file <none>
I20260812 06:17:32.854689 18540 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:32.854745 18540 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:32.854825 18540 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:32.855227 18540 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/instance:
uuid: "14fdcfb84b704ce586f7d30b7008b44e"
format_stamp: "Formatted at 2026-08-12 06:17:32 on dist-test-slave-1l3l"
I20260812 06:17:32.856850 18540 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:32.857821 18710 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:32.858052 18540 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:32.858122 18540 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root
uuid: "14fdcfb84b704ce586f7d30b7008b44e"
format_stamp: "Formatted at 2026-08-12 06:17:32 on dist-test-slave-1l3l"
I20260812 06:17:32.858199 18540 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:32.883783 18540 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:32.884335 18540 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:32.884841 18540 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:32.885739 18540 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:32.885795 18540 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:32.885842 18540 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:32.885870 18540 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:32.892223 18540 rpc_server.cc:307] RPC server started. Bound to: 127.18.27.1:40749
I20260812 06:17:32.892292 18816 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.27.1:40749 every 8 connection(s)
I20260812 06:17:32.906240 18817 heartbeater.cc:344] Connected to a master server at 127.18.27.62:45671
I20260812 06:17:32.906513 18817 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:32.907009 18817 heartbeater.cc:507] Master 127.18.27.62:45671 requested a full tablet report, sending...
I20260812 06:17:32.908516 18594 ts_manager.cc:194] Registered new tserver with Master: 14fdcfb84b704ce586f7d30b7008b44e (127.18.27.1:40749)
I20260812 06:17:32.909281 18540 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016423749s
I20260812 06:17:32.909720 18594 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37200
I20260812 06:17:32.922017 18594 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37216:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:32.938382 18752 tablet_service.cc:1511] Processing CreateTablet for tablet 3c2497270c404f41a63697b2cdd08c65 (DEFAULT_TABLE table=heavy-update-compaction-test [id=0628682af5b24ac4b842c40418399bb0]), partition=
I20260812 06:17:32.938861 18752 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3c2497270c404f41a63697b2cdd08c65. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:32.941569 18838 tablet_bootstrap.cc:492] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Bootstrap starting.
I20260812 06:17:32.942533 18838 tablet_bootstrap.cc:654] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:32.943737 18838 tablet_bootstrap.cc:492] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: No bootstrap required, opened a new log
I20260812 06:17:32.943857 18838 ts_tablet_manager.cc:1403] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:32.944372 18838 raft_consensus.cc:359] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "14fdcfb84b704ce586f7d30b7008b44e" member_type: VOTER last_known_addr { host: "127.18.27.1" port: 40749 } }
I20260812 06:17:32.944485 18838 raft_consensus.cc:385] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:32.944507 18838 raft_consensus.cc:740] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 14fdcfb84b704ce586f7d30b7008b44e, State: Initialized, Role: FOLLOWER
I20260812 06:17:32.944648 18838 consensus_queue.cc:260] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [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: "14fdcfb84b704ce586f7d30b7008b44e" member_type: VOTER last_known_addr { host: "127.18.27.1" port: 40749 } }
I20260812 06:17:32.944722 18838 raft_consensus.cc:399] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:32.944762 18838 raft_consensus.cc:493] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:32.944811 18838 raft_consensus.cc:3060] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:32.945664 18838 raft_consensus.cc:515] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "14fdcfb84b704ce586f7d30b7008b44e" member_type: VOTER last_known_addr { host: "127.18.27.1" port: 40749 } }
I20260812 06:17:32.945825 18838 leader_election.cc:304] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [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: 14fdcfb84b704ce586f7d30b7008b44e; no voters: 
I20260812 06:17:32.946058 18838 leader_election.cc:290] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:32.946171 18840 raft_consensus.cc:2804] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:32.946416 18838 ts_tablet_manager.cc:1434] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:32.946637 18817 heartbeater.cc:499] Master 127.18.27.62:45671 was elected leader, sending a full tablet report...
I20260812 06:17:32.946436 18840 raft_consensus.cc:697] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [term 1 LEADER]: Becoming Leader. State: Replica: 14fdcfb84b704ce586f7d30b7008b44e, State: Running, Role: LEADER
I20260812 06:17:32.947029 18840 consensus_queue.cc:237] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [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: "14fdcfb84b704ce586f7d30b7008b44e" member_type: VOTER last_known_addr { host: "127.18.27.1" port: 40749 } }
I20260812 06:17:32.949954 18594 catalog_manager.cc:5719] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e reported cstate change: term changed from 0 to 1, leader changed from <none> to 14fdcfb84b704ce586f7d30b7008b44e (127.18.27.1). New cstate: current_term: 1 leader_uuid: "14fdcfb84b704ce586f7d30b7008b44e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "14fdcfb84b704ce586f7d30b7008b44e" member_type: VOTER last_known_addr { host: "127.18.27.1" port: 40749 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:33.011288 18540 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.018s	sys 0.007s
I20260812 06:17:33.143501 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushMRSOp(3c2497270c404f41a63697b2cdd08c65): perf score=17.070565
I20260812 06:17:33.290766 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushMRSOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.147s	user 0.093s	sys 0.049s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":440,"delete_count":0,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":852,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34205,"lbm_writes_lt_1ms":667,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":137,"threads_started":1,"update_count":1050}
I20260812 06:17:33.291915 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling LogGCOp(3c2497270c404f41a63697b2cdd08c65): free 20743880 bytes of WAL
I20260812 06:17:33.292210 18717 log_reader.cc:385] T 3c2497270c404f41a63697b2cdd08c65: removed 2 log segments from log reader
I20260812 06:17:33.292274 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000001 (ops 1-6)
I20260812 06:17:33.292333 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000002 (ops 7-11)
I20260812 06:17:33.297677 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: LogGCOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:33.298154 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling UndoDeltaBlockGCOp(3c2497270c404f41a63697b2cdd08c65): 16411395 bytes on disk
I20260812 06:17:33.298975 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: UndoDeltaBlockGCOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:17:33.299549 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:33.316157 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5517,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.316748 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:33.434442 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.118s	user 0.094s	sys 0.018s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":758,"lbm_read_time_us":7387,"lbm_reads_lt_1ms":360,"lbm_write_time_us":20255,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":266,"threads_started":5,"update_count":1500}
I20260812 06:17:33.434950 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:33.487665 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.053s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16693,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.488227 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:33.503644 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.504158 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:33.623050 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.119s	user 0.099s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1029,"lbm_read_time_us":8282,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20650,"lbm_writes_lt_1ms":443,"mutex_wait_us":329,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:17:33.623584 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:33.671880 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.048s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14403,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.672569 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:33.683387 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":3943,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.684018 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:33.829265 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.145s	user 0.075s	sys 0.069s 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":1015,"lbm_read_time_us":10797,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23293,"lbm_writes_lt_1ms":443,"mutex_wait_us":315,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:33.829909 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:33.861255 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.031s	user 0.011s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":11690,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:33.861725 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:33.966161 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.104s	user 0.100s	sys 0.004s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569748,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":254,"lbm_read_time_us":7353,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17178,"lbm_writes_lt_1ms":343,"mutex_wait_us":55,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":1500}
I20260812 06:17:33.966713 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:34.004294 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.037s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13788,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.004801 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:34.015033 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3727,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.015791 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:34.137979 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.122s	user 0.109s	sys 0.013s 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":324,"lbm_read_time_us":7605,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22243,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:34.138576 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:34.168603 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.030s	user 0.021s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12536,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.169234 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:34.282752 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.113s	user 0.083s	sys 0.025s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":481,"lbm_read_time_us":5884,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17873,"lbm_writes_lt_1ms":343,"mutex_wait_us":27,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":55424,"update_count":1500}
I20260812 06:17:34.283264 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:34.332165 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.049s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16044,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.332756 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:34.343395 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.344048 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:34.465094 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.121s	user 0.100s	sys 0.020s 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":160,"lbm_read_time_us":9611,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22532,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":44928,"update_count":2000}
I20260812 06:17:34.465629 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:34.510311 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.045s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15176,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:34.510833 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:34.522002 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3844,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.522576 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushMRSOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:34.554872 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushMRSOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1304,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1910,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:34.555773 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling LogGCOp(3c2497270c404f41a63697b2cdd08c65): free 112692363 bytes of WAL
I20260812 06:17:34.556012 18717 log_reader.cc:385] T 3c2497270c404f41a63697b2cdd08c65: removed 11 log segments from log reader
I20260812 06:17:34.556058 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000003 (ops 12-16)
I20260812 06:17:34.556088 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000004 (ops 17-21)
I20260812 06:17:34.556118 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000005 (ops 22-26)
I20260812 06:17:34.556147 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000006 (ops 27-31)
I20260812 06:17:34.556181 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000007 (ops 32-36)
I20260812 06:17:34.556213 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000008 (ops 37-41)
I20260812 06:17:34.556245 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000009 (ops 42-46)
I20260812 06:17:34.556277 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000010 (ops 47-51)
I20260812 06:17:34.556308 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000011 (ops 52-56)
I20260812 06:17:34.556340 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000012 (ops 57-61)
I20260812 06:17:34.556380 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000013 (ops 62-66)
I20260812 06:17:34.577808 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: LogGCOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.022s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:34.578286 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=3.181125
I20260812 06:17:34.593994 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.016s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4104,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:34.594453 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:34.604082 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3407,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.604568 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:34.774457 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.170s	user 0.122s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":148,"lbm_read_time_us":11346,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32805,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13952,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:17:34.774947 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=14.095187
I20260812 06:17:34.829744 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.055s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":21297,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.830343 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:34.846519 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.847126 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:35.002475 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.155s	user 0.123s	sys 0.032s 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":239,"lbm_read_time_us":11752,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28629,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2500}
I20260812 06:17:35.003283 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=12.110812
I20260812 06:17:35.041567 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.038s	user 0.020s	sys 0.016s Metrics: {"bytes_written":13538209,"delete_count":0,"lbm_write_time_us":16096,"lbm_writes_lt_1ms":333,"reinsert_count":0,"update_count":1650}
I20260812 06:17:35.042171 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling UndoDeltaBlockGCOp(3c2497270c404f41a63697b2cdd08c65): 462 bytes on disk
I20260812 06:17:35.042745 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: UndoDeltaBlockGCOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:17:35.043325 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.196750
I20260812 06:17:35.054740 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:17:35.055370 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:35.185921 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.130s	user 0.110s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672242,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":49,"lbm_read_time_us":10579,"lbm_reads_lt_1ms":468,"lbm_write_time_us":20942,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2000}
I20260812 06:17:35.186569 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:35.217265 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.029s	user 0.007s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12513,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.217881 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:35.233251 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.233875 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:35.366916 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.133s	user 0.096s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":10038,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21851,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:35.367507 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:35.412622 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.045s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14618,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.413229 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:35.424185 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3811,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.424911 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:35.547591 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.122s	user 0.102s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":566,"lbm_read_time_us":8312,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22598,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2000}
I20260812 06:17:35.548277 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:35.590982 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.043s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14925,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.591521 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:35.602594 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.603300 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:35.723882 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.120s	user 0.078s	sys 0.039s 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":718,"lbm_read_time_us":8470,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22045,"lbm_writes_lt_1ms":443,"mutex_wait_us":301,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:35.724418 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:35.764604 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.040s	user 0.027s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13672,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.765183 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:35.777930 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4911,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.778484 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:35.908280 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.130s	user 0.094s	sys 0.036s 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":285,"lbm_read_time_us":10249,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20869,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.908898 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:35.951485 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.042s	user 0.015s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14502,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:35.952016 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:35.962791 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3999,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.963331 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushMRSOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:35.996474 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushMRSOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.032s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1179,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1586,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:35.997186 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling LogGCOp(3c2497270c404f41a63697b2cdd08c65): free 133024380 bytes of WAL
I20260812 06:17:35.997401 18717 log_reader.cc:385] T 3c2497270c404f41a63697b2cdd08c65: removed 13 log segments from log reader
I20260812 06:17:35.997447 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000014 (ops 67-71)
I20260812 06:17:35.997475 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000015 (ops 72-76)
I20260812 06:17:35.997500 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000016 (ops 77-81)
I20260812 06:17:35.997530 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000017 (ops 82-86)
I20260812 06:17:35.997562 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000018 (ops 87-91)
I20260812 06:17:35.997593 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000019 (ops 92-96)
I20260812 06:17:35.997625 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000020 (ops 97-101)
I20260812 06:17:35.997655 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000021 (ops 102-106)
I20260812 06:17:35.997686 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000022 (ops 107-110)
I20260812 06:17:35.997717 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000023 (ops 111-115)
I20260812 06:17:35.997747 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000024 (ops 116-120)
I20260812 06:17:35.997778 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000025 (ops 121-125)
I20260812 06:17:35.997809 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000026 (ops 126-130)
I20260812 06:17:36.025924 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: LogGCOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:36.026425 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling UndoDeltaBlockGCOp(3c2497270c404f41a63697b2cdd08c65): 483 bytes on disk
I20260812 06:17:36.027071 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: UndoDeltaBlockGCOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:17:36.027770 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=5.165500
I20260812 06:17:36.058283 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.030s	user 0.015s	sys 0.012s Metrics: {"bytes_written":6974354,"delete_count":0,"lbm_write_time_us":8626,"lbm_writes_lt_1ms":173,"reinsert_count":0,"update_count":850}
I20260812 06:17:36.059056 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:36.066365 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1230902,"delete_count":0,"lbm_write_time_us":1937,"lbm_writes_lt_1ms":33,"reinsert_count":0,"update_count":150}
I20260812 06:17:36.066843 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:36.268680 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.202s	user 0.174s	sys 0.027s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":566,"lbm_read_time_us":14143,"lbm_reads_lt_1ms":666,"lbm_write_time_us":33495,"lbm_writes_lt_1ms":643,"mutex_wait_us":457,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12160,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:17:36.269203 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=14.095187
I20260812 06:17:36.328471 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.059s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20884,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.329073 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:36.344741 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5823,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.345322 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:36.518810 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.173s	user 0.102s	sys 0.065s 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":952,"lbm_read_time_us":13372,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27103,"lbm_writes_lt_1ms":543,"mutex_wait_us":283,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:17:36.519439 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=11.118625
I20260812 06:17:36.564957 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.045s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17832,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:36.565508 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:36.582593 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.017s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.583096 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:36.600950 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.018s	user 0.005s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3435,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.601724 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:36.778565 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.177s	user 0.090s	sys 0.082s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":234,"lbm_read_time_us":13429,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28565,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:36.779260 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=11.118625
I20260812 06:17:36.822645 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.043s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18068,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:36.823302 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:36.839789 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.016s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":3870,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.840266 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:36.849848 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3314,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.850363 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:37.025776 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.175s	user 0.112s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":289,"lbm_read_time_us":9748,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27929,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:37.026381 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=14.095187
I20260812 06:17:37.075768 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.049s	user 0.018s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18359,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.076323 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:37.087666 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3836,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.088268 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:37.234579 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.146s	user 0.116s	sys 0.029s 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":690,"lbm_read_time_us":11779,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26919,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:17:37.235445 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:37.273447 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.038s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15982,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.273965 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:37.288630 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.289171 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:37.410524 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.121s	user 0.090s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":398,"lbm_read_time_us":9685,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23184,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2000}
I20260812 06:17:37.411808 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=10.126437
I20260812 06:17:37.446456 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.034s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13852,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:37.447060 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=2.188937
I20260812 06:17:37.462858 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.463526 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushMRSOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:37.498230 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushMRSOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1364,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1658,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:37.499119 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling LogGCOp(3c2497270c404f41a63697b2cdd08c65): free 124710569 bytes of WAL
I20260812 06:17:37.499398 18717 log_reader.cc:385] T 3c2497270c404f41a63697b2cdd08c65: removed 12 log segments from log reader
I20260812 06:17:37.499447 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000027 (ops 131-135)
I20260812 06:17:37.499486 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000028 (ops 136-140)
I20260812 06:17:37.499514 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000029 (ops 141-145)
I20260812 06:17:37.499545 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000030 (ops 146-150)
I20260812 06:17:37.499577 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000031 (ops 151-155)
I20260812 06:17:37.499607 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000032 (ops 156-160)
I20260812 06:17:37.499637 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000033 (ops 161-165)
I20260812 06:17:37.499668 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000034 (ops 166-170)
I20260812 06:17:37.499725 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000035 (ops 171-175)
I20260812 06:17:37.499763 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000036 (ops 176-180)
I20260812 06:17:37.499787 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000037 (ops 181-185)
I20260812 06:17:37.499815 18717 log.cc:1079] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/3c2497270c404f41a63697b2cdd08c65/wal-000000038 (ops 186-190)
I20260812 06:17:37.526616 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: LogGCOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.027s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:37.527179 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling UndoDeltaBlockGCOp(3c2497270c404f41a63697b2cdd08c65): 472 bytes on disk
I20260812 06:17:37.527751 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: UndoDeltaBlockGCOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:17:37.528318 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=4.173312
I20260812 06:17:37.546926 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.018s	user 0.009s	sys 0.007s Metrics: {"bytes_written":6112849,"delete_count":0,"lbm_write_time_us":7263,"lbm_writes_lt_1ms":152,"reinsert_count":0,"update_count":745}
I20260812 06:17:37.547493 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:37.557770 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2092427,"delete_count":0,"lbm_write_time_us":3401,"lbm_writes_lt_1ms":54,"reinsert_count":0,"update_count":255}
I20260812 06:17:37.558259 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65): perf score=1.000000
I20260812 06:17:37.731340 18540 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.720s	user 1.704s	sys 0.122s
I20260812 06:17:37.733930 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: MajorDeltaCompactionOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.175s	user 0.138s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877292,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":654,"lbm_read_time_us":12846,"lbm_reads_lt_1ms":666,"lbm_write_time_us":32842,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11648,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:17:37.734536 18818 maintenance_manager.cc:419] P 14fdcfb84b704ce586f7d30b7008b44e: Scheduling FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65): perf score=14.095187
I20260812 06:17:37.761046 18540 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.029s	user 0.004s	sys 0.000s
I20260812 06:17:37.761749 18540 tablet_server.cc:179] TabletServer@127.18.27.1:0 shutting down...
I20260812 06:17:37.772931 18717 maintenance_manager.cc:643] P 14fdcfb84b704ce586f7d30b7008b44e: FlushDeltaMemStoresOp(3c2497270c404f41a63697b2cdd08c65) complete. Timing: real 0.038s	user 0.025s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16797,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.773554 18540 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:37.773975 18540 tablet_replica.cc:333] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e: stopping tablet replica
I20260812 06:17:37.774241 18540 raft_consensus.cc:2243] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:37.774497 18540 raft_consensus.cc:2272] T 3c2497270c404f41a63697b2cdd08c65 P 14fdcfb84b704ce586f7d30b7008b44e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:37.789284 18540 tablet_server.cc:196] TabletServer@127.18.27.1:0 shutdown complete.
I20260812 06:17:37.794030 18540 master.cc:562] Master@127.18.27.62:45671 shutting down...
I20260812 06:17:37.797442 18540 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:37.797616 18540 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:37.797668 18540 tablet_replica.cc:333] T 00000000000000000000000000000000 P a4e6d0c6d1cd482f853274ec1aae1fc2: stopping tablet replica
I20260812 06:17:37.809837 18540 master.cc:584] Master@127.18.27.62:45671 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5178 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:37.886363 18540 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.27.62:33395
I20260812 06:17:37.886726 18540 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:37.888801 18870 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:37.888900 18877 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:17:37.888917 18873 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:17:37.888908 18540 server_base.cc:1061] running on GCE node
I20260812 06:17:37.889263 18540 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:37.889328 18540 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:37.889357 18540 hybrid_clock.cc:648] HybridClock initialized: now 1786515457889357 us; error 0 us; skew 500 ppm
I20260812 06:17:37.890184 18540 webserver.cc:533] Webserver started at http://127.18.27.62:43777/ using document root <none> and password file <none>
I20260812 06:17:37.890354 18540 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:37.890412 18540 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:37.890486 18540 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:37.890858 18540 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/master-0-root/instance:
uuid: "e00b61b2344a4019b9e7de714de3f57e"
format_stamp: "Formatted at 2026-08-12 06:17:37 on dist-test-slave-1l3l"
I20260812 06:17:37.892449 18540 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:37.893352 18884 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:37.893569 18540 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:37.893638 18540 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/master-0-root
uuid: "e00b61b2344a4019b9e7de714de3f57e"
format_stamp: "Formatted at 2026-08-12 06:17:37 on dist-test-slave-1l3l"
I20260812 06:17:37.893707 18540 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:37.915689 18540 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:37.916139 18540 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:37.920156 18540 rpc_server.cc:307] RPC server started. Bound to: 127.18.27.62:33395
I20260812 06:17:37.936483 18974 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:37.936506 18973 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.27.62:33395 every 8 connection(s)
I20260812 06:17:37.938500 18974 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e: Bootstrap starting.
I20260812 06:17:37.939350 18974 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:37.940508 18974 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e: No bootstrap required, opened a new log
I20260812 06:17:37.940922 18974 raft_consensus.cc:359] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e00b61b2344a4019b9e7de714de3f57e" member_type: VOTER }
I20260812 06:17:37.941007 18974 raft_consensus.cc:385] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:37.941040 18974 raft_consensus.cc:740] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e00b61b2344a4019b9e7de714de3f57e, State: Initialized, Role: FOLLOWER
I20260812 06:17:37.941190 18974 consensus_queue.cc:260] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [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: "e00b61b2344a4019b9e7de714de3f57e" member_type: VOTER }
I20260812 06:17:37.941263 18974 raft_consensus.cc:399] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:37.941301 18974 raft_consensus.cc:493] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:37.941362 18974 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:37.942090 18974 raft_consensus.cc:515] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e00b61b2344a4019b9e7de714de3f57e" member_type: VOTER }
I20260812 06:17:37.942220 18974 leader_election.cc:304] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [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: e00b61b2344a4019b9e7de714de3f57e; no voters: 
I20260812 06:17:37.942437 18974 leader_election.cc:290] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:37.942584 18977 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:37.942785 18977 raft_consensus.cc:697] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [term 1 LEADER]: Becoming Leader. State: Replica: e00b61b2344a4019b9e7de714de3f57e, State: Running, Role: LEADER
I20260812 06:17:37.942952 18974 sys_catalog.cc:565] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:37.942932 18977 consensus_queue.cc:237] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [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: "e00b61b2344a4019b9e7de714de3f57e" member_type: VOTER }
I20260812 06:17:37.943384 18979 sys_catalog.cc:455] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e00b61b2344a4019b9e7de714de3f57e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e00b61b2344a4019b9e7de714de3f57e" member_type: VOTER } }
I20260812 06:17:37.943478 18979 sys_catalog.cc:458] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:37.943410 18985 sys_catalog.cc:455] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [sys.catalog]: SysCatalogTable state changed. Reason: New leader e00b61b2344a4019b9e7de714de3f57e. Latest consensus state: current_term: 1 leader_uuid: "e00b61b2344a4019b9e7de714de3f57e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e00b61b2344a4019b9e7de714de3f57e" member_type: VOTER } }
I20260812 06:17:37.943524 18985 sys_catalog.cc:458] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:37.943760 18988 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:37.944648 18988 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:37.944850 18540 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:37.946439 18988 catalog_manager.cc:1383] Generated new cluster ID: 405553446c9147a9886db9dce78daffb
I20260812 06:17:37.946506 18988 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:37.963678 18988 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:37.964303 18988 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:37.969580 18988 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e: Generated new TSK 0
I20260812 06:17:37.969744 18988 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:37.977093 18540 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:37.978927 19012 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:37.979040 19015 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:37.979090 18540 server_base.cc:1061] running on GCE node
W20260812 06:17:37.979159 19013 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:17:37.979382 18540 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:37.979427 18540 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:37.979441 18540 hybrid_clock.cc:648] HybridClock initialized: now 1786515457979442 us; error 0 us; skew 500 ppm
I20260812 06:17:37.980326 18540 webserver.cc:533] Webserver started at http://127.18.27.1:41023/ using document root <none> and password file <none>
I20260812 06:17:37.980497 18540 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:37.980551 18540 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:37.980628 18540 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:37.981104 18540 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/instance:
uuid: "e9decb4c5f644e22965cb9dbe04ba80d"
format_stamp: "Formatted at 2026-08-12 06:17:37 on dist-test-slave-1l3l"
I20260812 06:17:37.982609 18540 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:37.983541 19022 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:37.983793 18540 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:37.983865 18540 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root
uuid: "e9decb4c5f644e22965cb9dbe04ba80d"
format_stamp: "Formatted at 2026-08-12 06:17:37 on dist-test-slave-1l3l"
I20260812 06:17:37.983937 18540 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:37.993080 18540 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:37.993475 18540 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:37.993777 18540 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:37.994246 18540 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:37.994284 18540 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:37.994329 18540 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:37.994359 18540 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:37.998555 18540 rpc_server.cc:307] RPC server started. Bound to: 127.18.27.1:38113
I20260812 06:17:37.998582 19122 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.27.1:38113 every 8 connection(s)
I20260812 06:17:38.006281 19124 heartbeater.cc:344] Connected to a master server at 127.18.27.62:33395
I20260812 06:17:38.006433 19124 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:38.006702 19124 heartbeater.cc:507] Master 127.18.27.62:33395 requested a full tablet report, sending...
I20260812 06:17:38.007393 18913 ts_manager.cc:194] Registered new tserver with Master: e9decb4c5f644e22965cb9dbe04ba80d (127.18.27.1:38113)
I20260812 06:17:38.007843 18540 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008888301s
I20260812 06:17:38.008361 18913 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58446
I20260812 06:17:38.015036 18913 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58448:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:38.023770 19068 tablet_service.cc:1511] Processing CreateTablet for tablet 621bcaceb53046a7a76412ef2d6d7c26 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b1b035b104f54575bbe105824ae9ac99]), partition=
I20260812 06:17:38.024098 19068 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 621bcaceb53046a7a76412ef2d6d7c26. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:38.026171 19149 tablet_bootstrap.cc:492] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Bootstrap starting.
I20260812 06:17:38.027050 19149 tablet_bootstrap.cc:654] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:38.028216 19149 tablet_bootstrap.cc:492] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: No bootstrap required, opened a new log
I20260812 06:17:38.028342 19149 ts_tablet_manager.cc:1403] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:38.028766 19149 raft_consensus.cc:359] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e9decb4c5f644e22965cb9dbe04ba80d" member_type: VOTER last_known_addr { host: "127.18.27.1" port: 38113 } }
I20260812 06:17:38.028868 19149 raft_consensus.cc:385] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:38.028899 19149 raft_consensus.cc:740] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e9decb4c5f644e22965cb9dbe04ba80d, State: Initialized, Role: FOLLOWER
I20260812 06:17:38.029074 19149 consensus_queue.cc:260] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [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: "e9decb4c5f644e22965cb9dbe04ba80d" member_type: VOTER last_known_addr { host: "127.18.27.1" port: 38113 } }
I20260812 06:17:38.029170 19149 raft_consensus.cc:399] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:38.029198 19149 raft_consensus.cc:493] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:38.029245 19149 raft_consensus.cc:3060] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:38.030085 19149 raft_consensus.cc:515] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e9decb4c5f644e22965cb9dbe04ba80d" member_type: VOTER last_known_addr { host: "127.18.27.1" port: 38113 } }
I20260812 06:17:38.030216 19149 leader_election.cc:304] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [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: e9decb4c5f644e22965cb9dbe04ba80d; no voters: 
I20260812 06:17:38.030400 19149 leader_election.cc:290] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:38.030537 19152 raft_consensus.cc:2804] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:38.030726 19149 ts_tablet_manager.cc:1434] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:38.030764 19152 raft_consensus.cc:697] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [term 1 LEADER]: Becoming Leader. State: Replica: e9decb4c5f644e22965cb9dbe04ba80d, State: Running, Role: LEADER
I20260812 06:17:38.030781 19124 heartbeater.cc:499] Master 127.18.27.62:33395 was elected leader, sending a full tablet report...
I20260812 06:17:38.030975 19152 consensus_queue.cc:237] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [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: "e9decb4c5f644e22965cb9dbe04ba80d" member_type: VOTER last_known_addr { host: "127.18.27.1" port: 38113 } }
I20260812 06:17:38.032521 18913 catalog_manager.cc:5719] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d reported cstate change: term changed from 0 to 1, leader changed from <none> to e9decb4c5f644e22965cb9dbe04ba80d (127.18.27.1). New cstate: current_term: 1 leader_uuid: "e9decb4c5f644e22965cb9dbe04ba80d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e9decb4c5f644e22965cb9dbe04ba80d" member_type: VOTER last_known_addr { host: "127.18.27.1" port: 38113 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:38.094143 18540 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.015s	sys 0.008s
I20260812 06:17:38.249459 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushMRSOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=19.054940
I20260812 06:17:38.403941 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushMRSOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.154s	user 0.110s	sys 0.044s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":911,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38083,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:38.404702 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling LogGCOp(621bcaceb53046a7a76412ef2d6d7c26): free 20743880 bytes of WAL
I20260812 06:17:38.404984 19032 log_reader.cc:385] T 621bcaceb53046a7a76412ef2d6d7c26: removed 2 log segments from log reader
I20260812 06:17:38.405038 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000001 (ops 1-6)
I20260812 06:17:38.405069 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000002 (ops 7-11)
I20260812 06:17:38.408685 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: LogGCOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:38.409256 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:38.427080 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.427655 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:38.586611 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.159s	user 0.102s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":579,"lbm_read_time_us":9461,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27648,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":395,"threads_started":5,"update_count":2000}
I20260812 06:17:38.587124 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling UndoDeltaBlockGCOp(621bcaceb53046a7a76412ef2d6d7c26): 16411393 bytes on disk
I20260812 06:17:38.587529 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: UndoDeltaBlockGCOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:17:38.588034 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:38.631822 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.044s	user 0.017s	sys 0.025s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18577,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.632313 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:38.643321 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3762,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.644081 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:38.792811 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.148s	user 0.107s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1092,"lbm_read_time_us":10562,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26700,"lbm_writes_lt_1ms":543,"mutex_wait_us":331,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:38.793710 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=12.110812
I20260812 06:17:38.842620 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.049s	user 0.020s	sys 0.024s Metrics: {"bytes_written":14399712,"delete_count":0,"lbm_write_time_us":22902,"lbm_writes_lt_1ms":354,"reinsert_count":0,"update_count":1755}
I20260812 06:17:38.843108 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.196750
I20260812 06:17:38.854363 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.011s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2420633,"delete_count":0,"lbm_write_time_us":2333,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:17:38.854868 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:38.864492 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3460,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:38.864965 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:39.047163 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.182s	user 0.137s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":160,"lbm_read_time_us":12935,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30119,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:17:39.047667 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:39.106639 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.059s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19320,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.107229 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:39.122851 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5641,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.123548 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:39.284817 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.161s	user 0.100s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":172,"lbm_read_time_us":10811,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27512,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:17:39.285362 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:39.345106 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.060s	user 0.019s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19044,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.345664 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:39.356097 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.356683 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:39.526463 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.170s	user 0.111s	sys 0.047s 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":907,"lbm_read_time_us":12600,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24694,"lbm_writes_lt_1ms":543,"mutex_wait_us":279,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:17:39.529320 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:39.580389 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.051s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18765,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.580991 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:39.591609 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3999,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.592113 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushMRSOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:39.632375 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushMRSOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.040s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1315,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1530,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:39.633044 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling LogGCOp(621bcaceb53046a7a76412ef2d6d7c26): free 112239318 bytes of WAL
I20260812 06:17:39.633272 19032 log_reader.cc:385] T 621bcaceb53046a7a76412ef2d6d7c26: removed 11 log segments from log reader
I20260812 06:17:39.633319 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000003 (ops 12-16)
I20260812 06:17:39.633348 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000004 (ops 17-21)
I20260812 06:17:39.633378 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000005 (ops 22-26)
I20260812 06:17:39.633406 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000006 (ops 27-31)
I20260812 06:17:39.633438 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000007 (ops 32-36)
I20260812 06:17:39.633471 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000008 (ops 37-41)
I20260812 06:17:39.633502 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000009 (ops 42-46)
I20260812 06:17:39.633533 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000010 (ops 47-50)
I20260812 06:17:39.633564 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000011 (ops 51-55)
I20260812 06:17:39.633597 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000012 (ops 56-60)
I20260812 06:17:39.633628 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000013 (ops 61-65)
I20260812 06:17:39.653158 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: LogGCOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.020s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:17:39.653590 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling UndoDeltaBlockGCOp(621bcaceb53046a7a76412ef2d6d7c26): 462 bytes on disk
I20260812 06:17:39.654006 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: UndoDeltaBlockGCOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:39.654450 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:39.677461 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.023s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5210,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.677968 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:39.688203 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3717,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.688851 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:39.923031 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.234s	user 0.133s	sys 0.083s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":719,"lbm_read_time_us":16429,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36827,"lbm_writes_lt_1ms":743,"mutex_wait_us":79,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:17:39.926578 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=18.063937
I20260812 06:17:39.983134 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.056s	user 0.033s	sys 0.016s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":23178,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:39.983742 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:40.000137 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.016s	user 0.003s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6322,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.000595 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:40.185163 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.184s	user 0.136s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":623,"lbm_read_time_us":15373,"lbm_reads_lt_1ms":672,"lbm_write_time_us":30901,"lbm_writes_lt_1ms":643,"mutex_wait_us":324,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:17:40.185820 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:40.225997 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.040s	user 0.014s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17539,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.226548 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:40.242223 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5420,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.242697 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:40.406855 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.164s	user 0.117s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1394,"lbm_read_time_us":11481,"lbm_reads_lt_1ms":568,"lbm_write_time_us":26301,"lbm_writes_lt_1ms":543,"mutex_wait_us":550,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:17:40.407482 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:40.466948 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.059s	user 0.027s	sys 0.015s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":19795,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.467558 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:40.484136 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.484652 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:40.648561 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.164s	user 0.100s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":858,"lbm_read_time_us":12721,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26696,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:17:40.649196 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:40.709043 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.060s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19821,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.709646 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:40.720863 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3986,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.721411 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:40.887472 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.166s	user 0.108s	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":224,"lbm_read_time_us":13077,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26007,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2500}
I20260812 06:17:40.888165 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:40.938433 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.050s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17891,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:40.939035 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:40.949685 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3984,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.950240 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushMRSOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:40.978933 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushMRSOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.028s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1438,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1331,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:40.979768 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:41.157342 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.177s	user 0.112s	sys 0.065s 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":675,"lbm_read_time_us":12762,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30448,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:17:41.157927 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling LogGCOp(621bcaceb53046a7a76412ef2d6d7c26): free 124710298 bytes of WAL
I20260812 06:17:41.158149 19032 log_reader.cc:385] T 621bcaceb53046a7a76412ef2d6d7c26: removed 12 log segments from log reader
I20260812 06:17:41.158195 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000014 (ops 66-70)
I20260812 06:17:41.158233 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000015 (ops 71-75)
I20260812 06:17:41.158265 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000016 (ops 76-80)
I20260812 06:17:41.158324 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000017 (ops 81-85)
I20260812 06:17:41.158370 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000018 (ops 86-90)
I20260812 06:17:41.158425 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000019 (ops 91-95)
I20260812 06:17:41.158460 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000020 (ops 96-100)
I20260812 06:17:41.158514 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000021 (ops 101-105)
I20260812 06:17:41.158548 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000022 (ops 106-110)
I20260812 06:17:41.158601 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000023 (ops 111-115)
I20260812 06:17:41.158636 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000024 (ops 116-120)
I20260812 06:17:41.158691 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000025 (ops 121-125)
I20260812 06:17:41.186671 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: LogGCOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:41.187227 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=16.079562
I20260812 06:17:41.249877 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.062s	user 0.030s	sys 0.023s Metrics: {"bytes_written":18502131,"delete_count":0,"lbm_write_time_us":20709,"lbm_writes_lt_1ms":454,"reinsert_count":0,"update_count":2255}
I20260812 06:17:41.250460 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling UndoDeltaBlockGCOp(621bcaceb53046a7a76412ef2d6d7c26): 447 bytes on disk
I20260812 06:17:41.250916 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: UndoDeltaBlockGCOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:17:41.251428 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=4.173312
I20260812 06:17:41.265619 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":6112855,"delete_count":0,"lbm_write_time_us":5689,"lbm_writes_lt_1ms":152,"reinsert_count":0,"update_count":745}
I20260812 06:17:41.266235 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:41.461184 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.195s	user 0.126s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877108,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":224,"lbm_read_time_us":14418,"lbm_reads_lt_1ms":672,"lbm_write_time_us":30818,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24832,"update_count":3000}
I20260812 06:17:41.461766 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:41.514284 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.052s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21906,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.514842 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:41.526242 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4209,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.527016 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:41.698294 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.171s	user 0.095s	sys 0.074s 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":186,"lbm_read_time_us":11608,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29755,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:41.698844 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:41.760129 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.060s	user 0.024s	sys 0.029s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19020,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.760723 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:41.776202 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5818,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.776787 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:41.953521 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.176s	user 0.109s	sys 0.054s 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":173,"lbm_read_time_us":12865,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26399,"lbm_writes_lt_1ms":543,"mutex_wait_us":89,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":2500}
I20260812 06:17:41.954181 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:42.012449 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.058s	user 0.024s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22103,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.013235 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:42.029044 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.016s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5901,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.029659 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:42.214107 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.184s	user 0.114s	sys 0.061s 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":845,"lbm_read_time_us":13978,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28363,"lbm_writes_lt_1ms":543,"mutex_wait_us":272,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:17:42.214627 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:42.258703 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.044s	user 0.017s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17536,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.259258 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:42.270331 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3829,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.270876 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:42.450122 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.179s	user 0.122s	sys 0.047s 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":1034,"lbm_read_time_us":9799,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27796,"lbm_writes_lt_1ms":543,"mutex_wait_us":336,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:17:42.450670 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=14.095187
I20260812 06:17:42.520238 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.069s	user 0.033s	sys 0.006s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17694,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.520839 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:42.536171 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.536722 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushMRSOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:42.582988 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushMRSOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.046s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":1535,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1852,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:42.583877 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=3.181125
I20260812 06:17:42.599431 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.015s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4315,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:42.599958 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling LogGCOp(621bcaceb53046a7a76412ef2d6d7c26): free 124710558 bytes of WAL
I20260812 06:17:42.600179 19032 log_reader.cc:385] T 621bcaceb53046a7a76412ef2d6d7c26: removed 12 log segments from log reader
I20260812 06:17:42.600224 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000026 (ops 126-130)
I20260812 06:17:42.600255 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000027 (ops 131-135)
I20260812 06:17:42.600286 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000028 (ops 136-140)
I20260812 06:17:42.600317 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000029 (ops 141-145)
I20260812 06:17:42.600348 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000030 (ops 146-150)
I20260812 06:17:42.600382 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000031 (ops 151-155)
I20260812 06:17:42.600414 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000032 (ops 156-160)
I20260812 06:17:42.600453 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000033 (ops 161-165)
I20260812 06:17:42.600486 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000034 (ops 166-170)
I20260812 06:17:42.600518 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000035 (ops 171-175)
I20260812 06:17:42.600549 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000036 (ops 176-180)
I20260812 06:17:42.600580 19032 log.cc:1079] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: Deleting log segment in path: /tmp/dist-test-task5ndgZa/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515452697969-18540-0/minicluster-data/ts-0-root/wals/621bcaceb53046a7a76412ef2d6d7c26/wal-000000037 (ops 181-185)
I20260812 06:17:42.623186 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: LogGCOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:42.623729 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:42.646005 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.022s	user 0.004s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3644,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:42.646620 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=2.188937
I20260812 06:17:42.662185 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5488,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.662827 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=1.000000
I20260812 06:17:42.899761 18540 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.805s	user 1.711s	sys 0.222s
I20260812 06:17:42.908300 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: MajorDeltaCompactionOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.245s	user 0.169s	sys 0.072s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":556,"lbm_read_time_us":17749,"lbm_reads_lt_1ms":875,"lbm_write_time_us":40304,"lbm_writes_lt_1ms":843,"mutex_wait_us":27,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":8704,"thread_start_us":83,"threads_started":1,"update_count":4000}
I20260812 06:17:42.911901 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling UndoDeltaBlockGCOp(621bcaceb53046a7a76412ef2d6d7c26): 493 bytes on disk
I20260812 06:17:42.912694 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: UndoDeltaBlockGCOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:17:42.913288 19125 maintenance_manager.cc:419] P e9decb4c5f644e22965cb9dbe04ba80d: Scheduling FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26): perf score=18.063937
I20260812 06:17:42.940224 18540 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.040s	user 0.003s	sys 0.000s
I20260812 06:17:42.940733 18540 tablet_server.cc:179] TabletServer@127.18.27.1:0 shutting down...
I20260812 06:17:42.962746 19032 maintenance_manager.cc:643] P e9decb4c5f644e22965cb9dbe04ba80d: FlushDeltaMemStoresOp(621bcaceb53046a7a76412ef2d6d7c26) complete. Timing: real 0.049s	user 0.031s	sys 0.015s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":21884,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:42.963392 18540 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:42.963615 18540 tablet_replica.cc:333] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d: stopping tablet replica
I20260812 06:17:42.963804 18540 raft_consensus.cc:2243] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:42.963971 18540 raft_consensus.cc:2272] T 621bcaceb53046a7a76412ef2d6d7c26 P e9decb4c5f644e22965cb9dbe04ba80d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:42.967255 18540 tablet_server.cc:196] TabletServer@127.18.27.1:0 shutdown complete.
I20260812 06:17:42.980654 18540 master.cc:562] Master@127.18.27.62:33395 shutting down...
I20260812 06:17:42.983908 18540 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:42.984092 18540 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:42.984163 18540 tablet_replica.cc:333] T 00000000000000000000000000000000 P e00b61b2344a4019b9e7de714de3f57e: stopping tablet replica
I20260812 06:17:42.996497 18540 master.cc:584] Master@127.18.27.62:33395 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5188 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10367 ms total)

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