[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:48.638624 11669 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.101.126:36955
I20260812 06:16:48.639744 11669 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:48.640372 11669 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:48.647003 11677 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:48.647075 11669 server_base.cc:1061] running on GCE node
W20260812 06:16:48.647006 11680 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:48.647333 11676 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:48.647814 11669 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:48.647936 11669 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:48.648195 11669 hybrid_clock.cc:648] HybridClock initialized: now 1786515408648188 us; error 0 us; skew 500 ppm
I20260812 06:16:48.650224 11669 webserver.cc:533] Webserver started at http://127.11.101.126:43045/ using document root <none> and password file <none>
I20260812 06:16:48.650859 11669 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:48.650956 11669 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:48.651280 11669 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:48.652956 11669 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/master-0-root/instance:
uuid: "ec33c1b3249444f18f21594502c17c8e"
format_stamp: "Formatted at 2026-08-12 06:16:48 on dist-test-slave-vkjp"
I20260812 06:16:48.656590 11669 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:16:48.658636 11685 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:48.659822 11669 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:48.659966 11669 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/master-0-root
uuid: "ec33c1b3249444f18f21594502c17c8e"
format_stamp: "Formatted at 2026-08-12 06:16:48 on dist-test-slave-vkjp"
I20260812 06:16:48.660074 11669 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:48.673182 11669 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:48.673833 11669 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:48.674026 11669 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:48.682052 11669 rpc_server.cc:307] RPC server started. Bound to: 127.11.101.126:36955
I20260812 06:16:48.682062 11749 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.101.126:36955 every 8 connection(s)
I20260812 06:16:48.684334 11750 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:48.689795 11750 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e: Bootstrap starting.
I20260812 06:16:48.692145 11750 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:48.693079 11750 log.cc:826] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:48.694804 11750 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e: No bootstrap required, opened a new log
I20260812 06:16:48.697551 11750 raft_consensus.cc:359] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ec33c1b3249444f18f21594502c17c8e" member_type: VOTER }
I20260812 06:16:48.697710 11750 raft_consensus.cc:385] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:48.697780 11750 raft_consensus.cc:740] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ec33c1b3249444f18f21594502c17c8e, State: Initialized, Role: FOLLOWER
I20260812 06:16:48.698366 11750 consensus_queue.cc:260] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [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: "ec33c1b3249444f18f21594502c17c8e" member_type: VOTER }
I20260812 06:16:48.698526 11750 raft_consensus.cc:399] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:48.698604 11750 raft_consensus.cc:493] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:48.698760 11750 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:48.699602 11750 raft_consensus.cc:515] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ec33c1b3249444f18f21594502c17c8e" member_type: VOTER }
I20260812 06:16:48.700026 11750 leader_election.cc:304] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [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: ec33c1b3249444f18f21594502c17c8e; no voters: 
I20260812 06:16:48.700356 11750 leader_election.cc:290] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:48.700551 11753 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:48.700845 11753 raft_consensus.cc:697] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [term 1 LEADER]: Becoming Leader. State: Replica: ec33c1b3249444f18f21594502c17c8e, State: Running, Role: LEADER
I20260812 06:16:48.701511 11753 consensus_queue.cc:237] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [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: "ec33c1b3249444f18f21594502c17c8e" member_type: VOTER }
I20260812 06:16:48.701596 11750 sys_catalog.cc:565] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:48.703588 11756 sys_catalog.cc:455] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [sys.catalog]: SysCatalogTable state changed. Reason: New leader ec33c1b3249444f18f21594502c17c8e. Latest consensus state: current_term: 1 leader_uuid: "ec33c1b3249444f18f21594502c17c8e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ec33c1b3249444f18f21594502c17c8e" member_type: VOTER } }
I20260812 06:16:48.703722 11756 sys_catalog.cc:458] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:48.703982 11754 sys_catalog.cc:455] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ec33c1b3249444f18f21594502c17c8e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ec33c1b3249444f18f21594502c17c8e" member_type: VOTER } }
I20260812 06:16:48.704069 11754 sys_catalog.cc:458] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:48.704075 11768 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:48.704134 11669 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:48.706262 11768 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:48.710678 11768 catalog_manager.cc:1383] Generated new cluster ID: 703a01c3db764ecaa9cbc88ff78fb64c
I20260812 06:16:48.710742 11768 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:48.727715 11768 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:48.728574 11768 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:48.738654 11768 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e: Generated new TSK 0
I20260812 06:16:48.739326 11768 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:48.768836 11669 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:48.771652 11777 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:48.771721 11775 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:48.771747 11779 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:48.771922 11669 server_base.cc:1061] running on GCE node
I20260812 06:16:48.772243 11669 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:48.772300 11669 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:48.772321 11669 hybrid_clock.cc:648] HybridClock initialized: now 1786515408772321 us; error 0 us; skew 500 ppm
I20260812 06:16:48.773311 11669 webserver.cc:533] Webserver started at http://127.11.101.65:40647/ using document root <none> and password file <none>
I20260812 06:16:48.773485 11669 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:48.773547 11669 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:48.773635 11669 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:48.774115 11669 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/instance:
uuid: "2469603ca78d4b07bdfbc5fc3e330d19"
format_stamp: "Formatted at 2026-08-12 06:16:48 on dist-test-slave-vkjp"
I20260812 06:16:48.776094 11669 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:48.777246 11785 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:48.777510 11669 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:48.777609 11669 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root
uuid: "2469603ca78d4b07bdfbc5fc3e330d19"
format_stamp: "Formatted at 2026-08-12 06:16:48 on dist-test-slave-vkjp"
I20260812 06:16:48.777705 11669 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:48.786996 11669 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:48.787482 11669 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:48.788048 11669 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:48.788954 11669 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:48.789047 11669 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:48.789155 11669 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:48.789206 11669 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:48.796815 11669 rpc_server.cc:307] RPC server started. Bound to: 127.11.101.65:44653
I20260812 06:16:48.796901 11857 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.101.65:44653 every 8 connection(s)
I20260812 06:16:48.809451 11859 heartbeater.cc:344] Connected to a master server at 127.11.101.126:36955
I20260812 06:16:48.809696 11859 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:48.810176 11859 heartbeater.cc:507] Master 127.11.101.126:36955 requested a full tablet report, sending...
I20260812 06:16:48.811782 11704 ts_manager.cc:194] Registered new tserver with Master: 2469603ca78d4b07bdfbc5fc3e330d19 (127.11.101.65:44653)
I20260812 06:16:48.811882 11669 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014329374s
I20260812 06:16:48.813318 11704 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47842
I20260812 06:16:48.822546 11704 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47850:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:48.840461 11816 tablet_service.cc:1511] Processing CreateTablet for tablet 1018c3a4e0374c6fa66303386fa7c465 (DEFAULT_TABLE table=heavy-update-compaction-test [id=34898ef175e54b94a5f387dda519d6d2]), partition=
I20260812 06:16:48.840929 11816 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1018c3a4e0374c6fa66303386fa7c465. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:48.844100 11872 tablet_bootstrap.cc:492] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Bootstrap starting.
I20260812 06:16:48.845278 11872 tablet_bootstrap.cc:654] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:48.846500 11872 tablet_bootstrap.cc:492] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: No bootstrap required, opened a new log
I20260812 06:16:48.846626 11872 ts_tablet_manager.cc:1403] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:48.847350 11872 raft_consensus.cc:359] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2469603ca78d4b07bdfbc5fc3e330d19" member_type: VOTER last_known_addr { host: "127.11.101.65" port: 44653 } }
I20260812 06:16:48.847476 11872 raft_consensus.cc:385] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:48.847561 11872 raft_consensus.cc:740] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2469603ca78d4b07bdfbc5fc3e330d19, State: Initialized, Role: FOLLOWER
I20260812 06:16:48.847739 11872 consensus_queue.cc:260] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [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: "2469603ca78d4b07bdfbc5fc3e330d19" member_type: VOTER last_known_addr { host: "127.11.101.65" port: 44653 } }
I20260812 06:16:48.847868 11872 raft_consensus.cc:399] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:48.847922 11872 raft_consensus.cc:493] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:48.847996 11872 raft_consensus.cc:3060] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:48.848877 11872 raft_consensus.cc:515] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2469603ca78d4b07bdfbc5fc3e330d19" member_type: VOTER last_known_addr { host: "127.11.101.65" port: 44653 } }
I20260812 06:16:48.849035 11872 leader_election.cc:304] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [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: 2469603ca78d4b07bdfbc5fc3e330d19; no voters: 
I20260812 06:16:48.849291 11872 leader_election.cc:290] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:48.849483 11874 raft_consensus.cc:2804] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:48.849716 11872 ts_tablet_manager.cc:1434] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:48.849800 11874 raft_consensus.cc:697] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [term 1 LEADER]: Becoming Leader. State: Replica: 2469603ca78d4b07bdfbc5fc3e330d19, State: Running, Role: LEADER
I20260812 06:16:48.849992 11859 heartbeater.cc:499] Master 127.11.101.126:36955 was elected leader, sending a full tablet report...
I20260812 06:16:48.849992 11874 consensus_queue.cc:237] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [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: "2469603ca78d4b07bdfbc5fc3e330d19" member_type: VOTER last_known_addr { host: "127.11.101.65" port: 44653 } }
I20260812 06:16:48.853168 11704 catalog_manager.cc:5719] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 reported cstate change: term changed from 0 to 1, leader changed from <none> to 2469603ca78d4b07bdfbc5fc3e330d19 (127.11.101.65). New cstate: current_term: 1 leader_uuid: "2469603ca78d4b07bdfbc5fc3e330d19" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2469603ca78d4b07bdfbc5fc3e330d19" member_type: VOTER last_known_addr { host: "127.11.101.65" port: 44653 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:48.954972 11669 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.094s	user 0.023s	sys 0.012s
I20260812 06:16:49.048043 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushMRSOp(1018c3a4e0374c6fa66303386fa7c465): perf score=10.125253
I20260812 06:16:49.203248 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushMRSOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.155s	user 0.109s	sys 0.036s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":275,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1087,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35256,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"thread_start_us":154,"threads_started":1,"update_count":1500}
I20260812 06:16:49.204367 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling LogGCOp(1018c3a4e0374c6fa66303386fa7c465): free 8725963 bytes of WAL
I20260812 06:16:49.204661 11790 log_reader.cc:385] T 1018c3a4e0374c6fa66303386fa7c465: removed 1 log segments from log reader
I20260812 06:16:49.204741 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000001 (ops 1-6)
I20260812 06:16:49.206554 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: LogGCOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:49.206853 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:49.219341 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4011,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.219923 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling UndoDeltaBlockGCOp(1018c3a4e0374c6fa66303386fa7c465): 8206537 bytes on disk
I20260812 06:16:49.220577 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: UndoDeltaBlockGCOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:16:49.221148 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:49.353922 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.132s	user 0.108s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":590,"lbm_read_time_us":8240,"lbm_reads_lt_1ms":460,"lbm_write_time_us":24349,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":288,"threads_started":5,"update_count":2000}
I20260812 06:16:49.354530 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=10.126437
I20260812 06:16:49.396332 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.042s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15574,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:49.396785 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:49.408030 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.408658 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:49.525096 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.116s	user 0.096s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":592,"lbm_read_time_us":8534,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21266,"lbm_writes_lt_1ms":443,"mutex_wait_us":276,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":67328,"update_count":2000}
I20260812 06:16:49.525758 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=10.126437
I20260812 06:16:49.580211 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.054s	user 0.042s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18917,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:49.580853 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:49.598407 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.599102 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:49.740567 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.141s	user 0.073s	sys 0.066s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":259,"lbm_read_time_us":10179,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23991,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:16:49.741199 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=10.126437
I20260812 06:16:49.787341 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.046s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14659,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:49.787886 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:49.804723 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6099,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.808071 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:49.933354 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.125s	user 0.104s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":998,"lbm_read_time_us":8243,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23975,"lbm_writes_lt_1ms":443,"mutex_wait_us":641,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":2000}
I20260812 06:16:49.935568 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=10.126437
I20260812 06:16:49.974960 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.039s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18072,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:49.975512 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:50.001513 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.026s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5441,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.001993 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:50.012796 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4018,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.013499 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:50.164170 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.150s	user 0.125s	sys 0.025s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692878,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1092,"lbm_read_time_us":11699,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30175,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2500}
I20260812 06:16:50.164897 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=10.126437
I20260812 06:16:50.200445 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.034s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14700,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:50.201110 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:50.216519 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.217001 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:50.340319 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.123s	user 0.095s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":8604,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24549,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:16:50.341236 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=10.126437
I20260812 06:16:50.379253 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.038s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14095,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:50.379838 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:50.392498 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4687,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.393113 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushMRSOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:50.428889 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushMRSOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.036s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":291,"dirs.run_wall_time_us":1492,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1886,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:50.429692 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling LogGCOp(1018c3a4e0374c6fa66303386fa7c465): free 120100266 bytes of WAL
I20260812 06:16:50.429972 11790 log_reader.cc:385] T 1018c3a4e0374c6fa66303386fa7c465: removed 12 log segments from log reader
I20260812 06:16:50.430047 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000002 (ops 7-11)
I20260812 06:16:50.430085 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000003 (ops 12-16)
I20260812 06:16:50.430116 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000004 (ops 17-21)
I20260812 06:16:50.430148 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000005 (ops 22-26)
I20260812 06:16:50.430177 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000006 (ops 27-30)
I20260812 06:16:50.430208 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000007 (ops 31-35)
I20260812 06:16:50.430234 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000008 (ops 36-40)
I20260812 06:16:50.430264 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000009 (ops 41-44)
I20260812 06:16:50.430291 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000010 (ops 45-49)
I20260812 06:16:50.430325 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000011 (ops 50-54)
I20260812 06:16:50.430354 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000012 (ops 55-58)
I20260812 06:16:50.430383 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000013 (ops 59-63)
I20260812 06:16:50.459636 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: LogGCOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:16:50.460069 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling UndoDeltaBlockGCOp(1018c3a4e0374c6fa66303386fa7c465): 462 bytes on disk
I20260812 06:16:50.460880 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: UndoDeltaBlockGCOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:16:50.461409 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:50.489538 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.028s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5595,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.490012 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:50.500206 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3881,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.500865 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:50.697620 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.197s	user 0.133s	sys 0.063s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795409,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":893,"lbm_read_time_us":12089,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35596,"lbm_writes_lt_1ms":643,"mutex_wait_us":198,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8576,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:16:50.698313 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=14.095187
I20260812 06:16:50.759411 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.061s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22168,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:50.759992 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:50.772173 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4464,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.772684 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:50.954763 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.182s	user 0.112s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692761,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":903,"lbm_read_time_us":13519,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31132,"lbm_writes_lt_1ms":543,"mutex_wait_us":248,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:16:50.955440 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=14.095187
I20260812 06:16:51.008719 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.053s	user 0.044s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25278,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.009243 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:51.020049 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.020493 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:51.206102 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.185s	user 0.120s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":12987,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35337,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:16:51.206624 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=14.095187
I20260812 06:16:51.271565 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.065s	user 0.029s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26071,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.272154 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:51.290324 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7262,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.290915 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:51.464316 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.173s	user 0.108s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692757,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1033,"lbm_read_time_us":12374,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29378,"lbm_writes_lt_1ms":543,"mutex_wait_us":79,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:16:51.465042 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=11.118625
I20260812 06:16:51.510596 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.045s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18618,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:16:51.511042 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:51.530205 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.019s	user 0.005s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4474,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.530884 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:51.540874 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3732,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:51.541549 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:51.726504 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.185s	user 0.141s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692869,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":593,"lbm_read_time_us":13075,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30056,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:16:51.727317 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=11.118625
I20260812 06:16:51.762244 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.035s	user 0.005s	sys 0.026s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15245,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:51.763748 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:51.788007 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6812,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:51.788481 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:51.800236 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4842,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.800863 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:51.978483 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.177s	user 0.124s	sys 0.050s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692870,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":523,"lbm_read_time_us":10645,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30965,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:16:51.979240 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=14.095187
I20260812 06:16:52.025892 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.046s	user 0.026s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22362,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:52.026521 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:52.038621 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4343,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.039290 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushMRSOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:52.072513 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushMRSOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.033s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1499,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2057,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:52.073275 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling LogGCOp(1018c3a4e0374c6fa66303386fa7c465): free 133024415 bytes of WAL
I20260812 06:16:52.073549 11790 log_reader.cc:385] T 1018c3a4e0374c6fa66303386fa7c465: removed 13 log segments from log reader
I20260812 06:16:52.073621 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000014 (ops 64-68)
I20260812 06:16:52.073676 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000015 (ops 69-73)
I20260812 06:16:52.073733 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000016 (ops 74-78)
I20260812 06:16:52.073776 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000017 (ops 79-82)
I20260812 06:16:52.073812 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000018 (ops 83-87)
I20260812 06:16:52.073849 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000019 (ops 88-92)
I20260812 06:16:52.073889 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000020 (ops 93-97)
I20260812 06:16:52.073925 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000021 (ops 98-102)
I20260812 06:16:52.073961 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000022 (ops 103-107)
I20260812 06:16:52.073999 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000023 (ops 108-112)
I20260812 06:16:52.074035 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000024 (ops 113-117)
I20260812 06:16:52.074071 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000025 (ops 118-122)
I20260812 06:16:52.074108 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000026 (ops 123-127)
I20260812 06:16:52.104977 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: LogGCOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:52.105448 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:52.122625 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.017s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4143684,"delete_count":0,"lbm_write_time_us":4465,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:16:52.123376 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:52.133872 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4061633,"delete_count":0,"lbm_write_time_us":4070,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:16:52.134387 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:52.355203 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.221s	user 0.144s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32897819,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":316,"lbm_read_time_us":14505,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39548,"lbm_writes_lt_1ms":743,"mutex_wait_us":53,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":19712,"thread_start_us":104,"threads_started":1,"update_count":3500}
I20260812 06:16:52.356669 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling UndoDeltaBlockGCOp(1018c3a4e0374c6fa66303386fa7c465): 493 bytes on disk
I20260812 06:16:52.357153 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: UndoDeltaBlockGCOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:16:52.357748 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=14.095187
I20260812 06:16:52.398778 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.041s	user 0.024s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18415,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:52.399380 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:52.412696 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.413159 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:52.587258 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.174s	user 0.113s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":493,"lbm_read_time_us":9982,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30863,"lbm_writes_lt_1ms":543,"mutex_wait_us":110,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:16:52.587925 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=14.095187
I20260812 06:16:52.651918 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.064s	user 0.029s	sys 0.033s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24405,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:16:52.652540 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:52.664795 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4691,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.665256 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:52.847656 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.182s	user 0.115s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":518,"lbm_read_time_us":11757,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30768,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:16:52.848248 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=14.095187
I20260812 06:16:52.907876 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.059s	user 0.026s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21831,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:52.908514 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:52.925345 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6260,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.925918 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:53.131884 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.206s	user 0.135s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":877,"lbm_read_time_us":11677,"lbm_reads_lt_1ms":572,"lbm_write_time_us":39640,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2500}
I20260812 06:16:53.132642 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=14.095187
I20260812 06:16:53.185000 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.052s	user 0.010s	sys 0.040s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23014,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:53.185627 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:53.205828 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3931,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.206420 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:53.382853 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.176s	user 0.140s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692757,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":246,"lbm_read_time_us":12043,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32538,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:16:53.383494 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=14.095187
I20260812 06:16:53.442991 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.059s	user 0.029s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":29381,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:53.443539 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:53.456485 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5403,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.456974 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:53.633788 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.177s	user 0.095s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1022,"lbm_read_time_us":11426,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31274,"lbm_writes_lt_1ms":543,"mutex_wait_us":427,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:16:53.634575 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=14.095187
I20260812 06:16:53.689730 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.055s	user 0.037s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27035,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:53.690177 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=2.188937
I20260812 06:16:53.702584 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5046,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:53.703461 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushMRSOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:53.731480 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushMRSOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.028s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":44,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1422,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1652,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:53.732223 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling LogGCOp(1018c3a4e0374c6fa66303386fa7c465): free 136728515 bytes of WAL
I20260812 06:16:53.732514 11790 log_reader.cc:385] T 1018c3a4e0374c6fa66303386fa7c465: removed 13 log segments from log reader
I20260812 06:16:53.732589 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000027 (ops 128-132)
I20260812 06:16:53.732642 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000028 (ops 133-137)
I20260812 06:16:53.732699 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000029 (ops 138-142)
I20260812 06:16:53.732743 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000030 (ops 143-147)
I20260812 06:16:53.732784 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000031 (ops 148-152)
I20260812 06:16:53.732820 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000032 (ops 153-157)
I20260812 06:16:53.732847 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000033 (ops 158-162)
I20260812 06:16:53.732887 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000034 (ops 163-167)
I20260812 06:16:53.732925 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000035 (ops 168-172)
I20260812 06:16:53.732967 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000036 (ops 173-177)
I20260812 06:16:53.733007 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000037 (ops 178-182)
I20260812 06:16:53.733062 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000038 (ops 183-187)
I20260812 06:16:53.733098 11790 log.cc:1079] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/1018c3a4e0374c6fa66303386fa7c465/wal-000000039 (ops 188-192)
I20260812 06:16:53.761231 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: LogGCOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:53.761687 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=4.173312
I20260812 06:16:53.782043 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.020s	user 0.013s	sys 0.004s Metrics: {"bytes_written":5989776,"delete_count":0,"lbm_write_time_us":8445,"lbm_writes_lt_1ms":149,"reinsert_count":0,"update_count":730}
I20260812 06:16:53.782558 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling UndoDeltaBlockGCOp(1018c3a4e0374c6fa66303386fa7c465): 492 bytes on disk
I20260812 06:16:53.783015 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: UndoDeltaBlockGCOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:16:53.783856 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.196750
I20260812 06:16:53.793746 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":2215504,"delete_count":0,"lbm_write_time_us":3288,"lbm_writes_lt_1ms":57,"reinsert_count":0,"update_count":270}
I20260812 06:16:53.794209 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465): perf score=1.000000
I20260812 06:16:53.934451 11669 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.979s	user 1.820s	sys 0.194s
I20260812 06:16:54.009464 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: MajorDeltaCompactionOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.215s	user 0.130s	sys 0.083s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32897775,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16237,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37495,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":3500}
I20260812 06:16:54.009981 11860 maintenance_manager.cc:419] P 2469603ca78d4b07bdfbc5fc3e330d19: Scheduling FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465): perf score=10.126437
I20260812 06:16:54.032270 11669 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.097s	user 0.001s	sys 0.002s
I20260812 06:16:54.032922 11669 tablet_server.cc:179] TabletServer@127.11.101.65:0 shutting down...
I20260812 06:16:54.052352 11790 maintenance_manager.cc:643] P 2469603ca78d4b07bdfbc5fc3e330d19: FlushDeltaMemStoresOp(1018c3a4e0374c6fa66303386fa7c465) complete. Timing: real 0.042s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14387,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:54.053155 11669 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:54.053689 11669 tablet_replica.cc:333] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19: stopping tablet replica
I20260812 06:16:54.054520 11669 raft_consensus.cc:2243] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:54.054831 11669 raft_consensus.cc:2272] T 1018c3a4e0374c6fa66303386fa7c465 P 2469603ca78d4b07bdfbc5fc3e330d19 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:54.071033 11669 tablet_server.cc:196] TabletServer@127.11.101.65:0 shutdown complete.
I20260812 06:16:54.075757 11669 master.cc:562] Master@127.11.101.126:36955 shutting down...
I20260812 06:16:54.079766 11669 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:54.079984 11669 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:54.080084 11669 tablet_replica.cc:333] T 00000000000000000000000000000000 P ec33c1b3249444f18f21594502c17c8e: stopping tablet replica
I20260812 06:16:54.092742 11669 master.cc:584] Master@127.11.101.126:36955 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5540 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:54.178552 11669 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.101.126:37995
I20260812 06:16:54.178974 11669 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:54.181428 11896 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:54.181452 11669 server_base.cc:1061] running on GCE node
W20260812 06:16:54.181489 11895 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:54.181607 11898 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:54.181849 11669 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:54.181905 11669 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:54.181922 11669 hybrid_clock.cc:648] HybridClock initialized: now 1786515414181922 us; error 0 us; skew 500 ppm
I20260812 06:16:54.182694 11669 webserver.cc:533] Webserver started at http://127.11.101.126:44283/ using document root <none> and password file <none>
I20260812 06:16:54.182823 11669 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:54.182861 11669 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:54.182936 11669 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:54.183383 11669 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/master-0-root/instance:
uuid: "8345b371d6274642b4e19309eaf5554b"
format_stamp: "Formatted at 2026-08-12 06:16:54 on dist-test-slave-vkjp"
I20260812 06:16:54.184844 11669 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:54.185715 11903 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:54.185941 11669 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:54.186033 11669 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/master-0-root
uuid: "8345b371d6274642b4e19309eaf5554b"
format_stamp: "Formatted at 2026-08-12 06:16:54 on dist-test-slave-vkjp"
I20260812 06:16:54.186120 11669 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:54.196792 11669 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:54.197190 11669 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:54.201390 11669 rpc_server.cc:307] RPC server started. Bound to: 127.11.101.126:37995
I20260812 06:16:54.203935 11960 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.101.126:37995 every 8 connection(s)
I20260812 06:16:54.209867 11961 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:54.212028 11961 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b: Bootstrap starting.
I20260812 06:16:54.212807 11961 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:54.213820 11961 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b: No bootstrap required, opened a new log
I20260812 06:16:54.214216 11961 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8345b371d6274642b4e19309eaf5554b" member_type: VOTER }
I20260812 06:16:54.214326 11961 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:54.214381 11961 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8345b371d6274642b4e19309eaf5554b, State: Initialized, Role: FOLLOWER
I20260812 06:16:54.214563 11961 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [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: "8345b371d6274642b4e19309eaf5554b" member_type: VOTER }
I20260812 06:16:54.214672 11961 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:54.214722 11961 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:54.214781 11961 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:54.215488 11961 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8345b371d6274642b4e19309eaf5554b" member_type: VOTER }
I20260812 06:16:54.215633 11961 leader_election.cc:304] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [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: 8345b371d6274642b4e19309eaf5554b; no voters: 
I20260812 06:16:54.215830 11961 leader_election.cc:290] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:54.215963 11965 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:54.216217 11965 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [term 1 LEADER]: Becoming Leader. State: Replica: 8345b371d6274642b4e19309eaf5554b, State: Running, Role: LEADER
I20260812 06:16:54.216298 11961 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:54.216352 11965 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [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: "8345b371d6274642b4e19309eaf5554b" member_type: VOTER }
I20260812 06:16:54.216804 11966 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8345b371d6274642b4e19309eaf5554b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8345b371d6274642b4e19309eaf5554b" member_type: VOTER } }
I20260812 06:16:54.216830 11967 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8345b371d6274642b4e19309eaf5554b. Latest consensus state: current_term: 1 leader_uuid: "8345b371d6274642b4e19309eaf5554b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8345b371d6274642b4e19309eaf5554b" member_type: VOTER } }
I20260812 06:16:54.216938 11966 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:54.217011 11967 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:54.217255 11972 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:54.218047 11972 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:54.218489 11669 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:54.220204 11972 catalog_manager.cc:1383] Generated new cluster ID: cc90a55d57704863b2cac4dcad614626
I20260812 06:16:54.220261 11972 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:54.229022 11972 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:54.229568 11972 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:54.250608 11972 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b: Generated new TSK 0
I20260812 06:16:54.250815 11972 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:54.283167 11669 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:54.285305 11989 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:54.285415 11669 server_base.cc:1061] running on GCE node
W20260812 06:16:54.285392 11985 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:54.285395 11984 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:54.285773 11669 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:54.285818 11669 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:54.285835 11669 hybrid_clock.cc:648] HybridClock initialized: now 1786515414285834 us; error 0 us; skew 500 ppm
I20260812 06:16:54.286651 11669 webserver.cc:533] Webserver started at http://127.11.101.65:42013/ using document root <none> and password file <none>
I20260812 06:16:54.286828 11669 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:54.286913 11669 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:54.286998 11669 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:54.287433 11669 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/instance:
uuid: "d2ece8234e2a4298a0846474e015a1f2"
format_stamp: "Formatted at 2026-08-12 06:16:54 on dist-test-slave-vkjp"
I20260812 06:16:54.288929 11669 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:54.289819 11995 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:54.290060 11669 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:54.290153 11669 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root
uuid: "d2ece8234e2a4298a0846474e015a1f2"
format_stamp: "Formatted at 2026-08-12 06:16:54 on dist-test-slave-vkjp"
I20260812 06:16:54.290238 11669 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:54.296716 11669 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:54.297060 11669 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:54.297361 11669 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:54.297808 11669 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:54.297875 11669 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:54.297952 11669 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:54.298003 11669 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:54.302342 11669 rpc_server.cc:307] RPC server started. Bound to: 127.11.101.65:46507
I20260812 06:16:54.302942 12068 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.101.65:46507 every 8 connection(s)
I20260812 06:16:54.311291 12069 heartbeater.cc:344] Connected to a master server at 127.11.101.126:37995
I20260812 06:16:54.311404 12069 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:54.311657 12069 heartbeater.cc:507] Master 127.11.101.126:37995 requested a full tablet report, sending...
I20260812 06:16:54.312392 11921 ts_manager.cc:194] Registered new tserver with Master: d2ece8234e2a4298a0846474e015a1f2 (127.11.101.65:46507)
I20260812 06:16:54.313021 11669 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.00986034s
I20260812 06:16:54.313217 11921 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47850
I20260812 06:16:54.320456 11921 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47860:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:54.328985 12029 tablet_service.cc:1511] Processing CreateTablet for tablet dd3f2620f9ac443c963ecd07df725bdb (DEFAULT_TABLE table=heavy-update-compaction-test [id=fd5be1e4af3d4c91a77f763252fb03a2]), partition=
I20260812 06:16:54.329278 12029 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet dd3f2620f9ac443c963ecd07df725bdb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:54.331547 12082 tablet_bootstrap.cc:492] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Bootstrap starting.
I20260812 06:16:54.332296 12082 tablet_bootstrap.cc:654] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:54.333346 12082 tablet_bootstrap.cc:492] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: No bootstrap required, opened a new log
I20260812 06:16:54.333420 12082 ts_tablet_manager.cc:1403] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:54.333770 12082 raft_consensus.cc:359] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2ece8234e2a4298a0846474e015a1f2" member_type: VOTER last_known_addr { host: "127.11.101.65" port: 46507 } }
I20260812 06:16:54.333850 12082 raft_consensus.cc:385] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:54.333873 12082 raft_consensus.cc:740] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d2ece8234e2a4298a0846474e015a1f2, State: Initialized, Role: FOLLOWER
I20260812 06:16:54.333977 12082 consensus_queue.cc:260] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [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: "d2ece8234e2a4298a0846474e015a1f2" member_type: VOTER last_known_addr { host: "127.11.101.65" port: 46507 } }
I20260812 06:16:54.334038 12082 raft_consensus.cc:399] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:54.334060 12082 raft_consensus.cc:493] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:54.334142 12082 raft_consensus.cc:3060] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:54.335011 12082 raft_consensus.cc:515] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2ece8234e2a4298a0846474e015a1f2" member_type: VOTER last_known_addr { host: "127.11.101.65" port: 46507 } }
I20260812 06:16:54.335211 12082 leader_election.cc:304] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [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: d2ece8234e2a4298a0846474e015a1f2; no voters: 
I20260812 06:16:54.335427 12082 leader_election.cc:290] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:54.335613 12084 raft_consensus.cc:2804] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:54.335786 12069 heartbeater.cc:499] Master 127.11.101.126:37995 was elected leader, sending a full tablet report...
I20260812 06:16:54.335850 12084 raft_consensus.cc:697] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [term 1 LEADER]: Becoming Leader. State: Replica: d2ece8234e2a4298a0846474e015a1f2, State: Running, Role: LEADER
I20260812 06:16:54.335785 12082 ts_tablet_manager.cc:1434] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:16:54.336021 12084 consensus_queue.cc:237] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [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: "d2ece8234e2a4298a0846474e015a1f2" member_type: VOTER last_known_addr { host: "127.11.101.65" port: 46507 } }
I20260812 06:16:54.337276 11921 catalog_manager.cc:5719] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 reported cstate change: term changed from 0 to 1, leader changed from <none> to d2ece8234e2a4298a0846474e015a1f2 (127.11.101.65). New cstate: current_term: 1 leader_uuid: "d2ece8234e2a4298a0846474e015a1f2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d2ece8234e2a4298a0846474e015a1f2" member_type: VOTER last_known_addr { host: "127.11.101.65" port: 46507 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:54.396834 11669 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.019s	sys 0.004s
I20260812 06:16:54.553872 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushMRSOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=20.047128
I20260812 06:16:54.724107 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushMRSOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.170s	user 0.130s	sys 0.036s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":980,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45163,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:16:54.724687 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling LogGCOp(dd3f2620f9ac443c963ecd07df725bdb): free 20743880 bytes of WAL
I20260812 06:16:54.724903 12002 log_reader.cc:385] T dd3f2620f9ac443c963ecd07df725bdb: removed 2 log segments from log reader
I20260812 06:16:54.724949 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000001 (ops 1-6)
I20260812 06:16:54.725009 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000002 (ops 7-11)
I20260812 06:16:54.729278 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: LogGCOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:54.729631 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling UndoDeltaBlockGCOp(dd3f2620f9ac443c963ecd07df725bdb): 20513815 bytes on disk
I20260812 06:16:54.730206 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: UndoDeltaBlockGCOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":108,"lbm_reads_lt_1ms":4}
I20260812 06:16:54.730886 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:54.744383 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4250,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.744876 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:54.899372 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.154s	user 0.082s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":670,"lbm_read_time_us":9391,"lbm_reads_lt_1ms":460,"lbm_write_time_us":26320,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":385,"threads_started":5,"update_count":2000}
I20260812 06:16:54.899957 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:54.957837 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.058s	user 0.034s	sys 0.018s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":25126,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:54.958272 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:54.968426 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:54.969051 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:55.166615 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.197s	user 0.141s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1341,"lbm_read_time_us":13433,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29878,"lbm_writes_lt_1ms":543,"mutex_wait_us":398,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2500}
I20260812 06:16:55.167182 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:55.233150 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.066s	user 0.036s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22251,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.233611 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:55.244241 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.010s	user 0.009s	sys 0.000s 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:16:55.244894 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:55.423121 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.178s	user 0.126s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":923,"lbm_read_time_us":12851,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31579,"lbm_writes_lt_1ms":543,"mutex_wait_us":101,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:55.423725 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:55.479583 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.056s	user 0.042s	sys 0.005s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":19773,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.480209 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:55.497406 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6970,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.497895 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:55.676463 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.178s	user 0.122s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815679,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":207,"lbm_read_time_us":11092,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30296,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:16:55.677237 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:55.734169 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.057s	user 0.033s	sys 0.018s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22436,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.734683 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:55.745273 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:55.745735 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:55.927021 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.181s	user 0.120s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":250,"lbm_read_time_us":11806,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32334,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:16:55.927817 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:55.992049 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.064s	user 0.036s	sys 0.027s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25844,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:55.992633 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:56.003222 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4074,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.003715 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushMRSOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:56.045722 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushMRSOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.042s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":1348,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1398,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:56.046429 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling LogGCOp(dd3f2620f9ac443c963ecd07df725bdb): free 121006429 bytes of WAL
I20260812 06:16:56.046674 12002 log_reader.cc:385] T dd3f2620f9ac443c963ecd07df725bdb: removed 12 log segments from log reader
I20260812 06:16:56.046717 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000003 (ops 12-16)
I20260812 06:16:56.046746 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000004 (ops 17-21)
I20260812 06:16:56.046813 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000005 (ops 22-26)
I20260812 06:16:56.046845 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000006 (ops 27-31)
I20260812 06:16:56.046882 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000007 (ops 32-36)
I20260812 06:16:56.046924 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000008 (ops 37-41)
I20260812 06:16:56.046962 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000009 (ops 42-46)
I20260812 06:16:56.047009 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000010 (ops 47-51)
I20260812 06:16:56.047051 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000011 (ops 52-56)
I20260812 06:16:56.047118 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000012 (ops 57-60)
I20260812 06:16:56.047147 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000013 (ops 61-65)
I20260812 06:16:56.047184 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000014 (ops 66-70)
I20260812 06:16:56.072391 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: LogGCOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:56.072938 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling UndoDeltaBlockGCOp(dd3f2620f9ac443c963ecd07df725bdb): 463 bytes on disk
I20260812 06:16:56.073352 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: UndoDeltaBlockGCOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:16:56.073804 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:56.089531 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.016s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4225735,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":106,"mutex_wait_us":939,"reinsert_count":0,"update_count":515}
I20260812 06:16:56.090037 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:56.100386 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":3824,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:16:56.100992 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:56.351370 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.250s	user 0.160s	sys 0.081s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":551,"lbm_read_time_us":16344,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38670,"lbm_writes_lt_1ms":743,"mutex_wait_us":28,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17664,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:16:56.351975 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=18.063937
I20260812 06:16:56.423980 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.072s	user 0.031s	sys 0.030s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27642,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:56.424541 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:56.440233 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5737,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.440871 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:56.640471 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.199s	user 0.115s	sys 0.083s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":829,"lbm_read_time_us":13467,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33812,"lbm_writes_lt_1ms":643,"mutex_wait_us":71,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":3000}
I20260812 06:16:56.642330 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:56.700057 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.057s	user 0.045s	sys 0.011s Metrics: {"bytes_written":16615023,"delete_count":0,"lbm_write_time_us":26244,"lbm_writes_lt_1ms":408,"reinsert_count":0,"update_count":2025}
I20260812 06:16:56.700632 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:56.712771 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":4433,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:16:56.713264 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:56.884693 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.171s	user 0.113s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":11288,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28603,"lbm_writes_lt_1ms":543,"mutex_wait_us":101,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:56.885434 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:56.941795 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.056s	user 0.036s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24818,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:56.942637 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:56.953830 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4341,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:56.954540 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:57.135823 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.181s	user 0.104s	sys 0.071s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":176,"lbm_read_time_us":12428,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28701,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:16:57.136608 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:57.195937 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.059s	user 0.051s	sys 0.007s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21434,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.196532 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:57.207569 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4310,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.208024 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:57.401630 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.193s	user 0.101s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1350,"lbm_read_time_us":13398,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30641,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15872,"update_count":2500}
I20260812 06:16:57.402354 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:57.451130 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.049s	user 0.031s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18781,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:57.451737 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:57.480360 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.028s	user 0.008s	sys 0.017s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8621,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.481040 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushMRSOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:57.509887 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushMRSOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.029s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":264,"dirs.run_wall_time_us":1342,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1607,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:57.510669 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling LogGCOp(dd3f2620f9ac443c963ecd07df725bdb): free 112239330 bytes of WAL
I20260812 06:16:57.510944 12002 log_reader.cc:385] T dd3f2620f9ac443c963ecd07df725bdb: removed 11 log segments from log reader
I20260812 06:16:57.511006 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000015 (ops 71-74)
I20260812 06:16:57.511044 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000016 (ops 75-79)
I20260812 06:16:57.511075 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000017 (ops 80-84)
I20260812 06:16:57.511140 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000018 (ops 85-89)
I20260812 06:16:57.511175 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000019 (ops 90-94)
I20260812 06:16:57.511198 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000020 (ops 95-99)
I20260812 06:16:57.511220 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000021 (ops 100-104)
I20260812 06:16:57.511250 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000022 (ops 105-109)
I20260812 06:16:57.511282 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000023 (ops 110-114)
I20260812 06:16:57.511313 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000024 (ops 115-119)
I20260812 06:16:57.511337 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000025 (ops 120-124)
I20260812 06:16:57.537818 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: LogGCOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:16:57.538292 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling UndoDeltaBlockGCOp(dd3f2620f9ac443c963ecd07df725bdb): 447 bytes on disk
I20260812 06:16:57.538767 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: UndoDeltaBlockGCOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:57.539731 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:57.557049 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.017s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6041,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.557691 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling LogGCOp(dd3f2620f9ac443c963ecd07df725bdb): free 11564877 bytes of WAL
I20260812 06:16:57.557941 12002 log_reader.cc:385] T dd3f2620f9ac443c963ecd07df725bdb: removed 1 log segments from log reader
I20260812 06:16:57.558009 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000026 (ops 125-128)
I20260812 06:16:57.560598 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: LogGCOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:57.561065 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:57.784169 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.223s	user 0.165s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918215,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":677,"lbm_read_time_us":14134,"lbm_reads_lt_1ms":665,"lbm_write_time_us":35988,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":75648,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:16:57.784937 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=18.063937
I20260812 06:16:57.858510 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.073s	user 0.053s	sys 0.010s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":29928,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:57.859169 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:57.875144 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:57.875854 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:58.078522 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.202s	user 0.142s	sys 0.060s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":577,"lbm_read_time_us":15067,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33700,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":3000}
I20260812 06:16:58.079200 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:58.128134 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.049s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21345,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:16:58.128887 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:58.148872 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.020s	user 0.004s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.149371 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:58.324950 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.175s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":303,"lbm_read_time_us":11971,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30252,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2500}
I20260812 06:16:58.325636 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:58.374815 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.049s	user 0.028s	sys 0.017s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":20458,"lbm_writes_lt_1ms":413,"mutex_wait_us":1243,"reinsert_count":0,"update_count":2050}
I20260812 06:16:58.375612 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:58.388830 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5167,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:58.389484 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:58.568297 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.179s	user 0.135s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815671,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":880,"lbm_read_time_us":11348,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30089,"lbm_writes_lt_1ms":543,"mutex_wait_us":286,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:16:58.569060 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:58.627017 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.058s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21184,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:58.627813 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:58.643150 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5713,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.643698 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:58.814218 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.170s	user 0.118s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":387,"lbm_read_time_us":11321,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29998,"lbm_writes_lt_1ms":543,"mutex_wait_us":84,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:16:58.815160 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:58.875628 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.060s	user 0.040s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22761,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:58.876389 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:58.888578 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:58.889038 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:59.069061 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.180s	user 0.132s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":697,"lbm_read_time_us":12529,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28445,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:59.072932 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=14.095187
I20260812 06:16:59.128858 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.056s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25666,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:59.129459 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:59.159204 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.030s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4225735,"delete_count":0,"lbm_write_time_us":5391,"lbm_writes_lt_1ms":106,"reinsert_count":0,"update_count":515}
I20260812 06:16:59.159741 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:59.170329 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4198,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:16:59.170888 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushMRSOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:59.206254 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushMRSOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.035s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1357582,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1560,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1751,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:16:59.206898 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling LogGCOp(dd3f2620f9ac443c963ecd07df725bdb): free 129320722 bytes of WAL
I20260812 06:16:59.207175 12002 log_reader.cc:385] T dd3f2620f9ac443c963ecd07df725bdb: removed 13 log segments from log reader
I20260812 06:16:59.207252 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000027 (ops 129-133)
I20260812 06:16:59.207307 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000028 (ops 134-138)
I20260812 06:16:59.207355 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000029 (ops 139-143)
I20260812 06:16:59.207397 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000030 (ops 144-148)
I20260812 06:16:59.207436 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000031 (ops 149-152)
I20260812 06:16:59.207491 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000032 (ops 153-157)
I20260812 06:16:59.207528 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000033 (ops 158-162)
I20260812 06:16:59.207568 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000034 (ops 163-167)
I20260812 06:16:59.207607 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000035 (ops 168-172)
I20260812 06:16:59.207643 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000036 (ops 173-176)
I20260812 06:16:59.207681 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000037 (ops 177-181)
I20260812 06:16:59.207719 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000038 (ops 182-186)
I20260812 06:16:59.207758 12002 log.cc:1079] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: Deleting log segment in path: /tmp/dist-test-taskebaHU6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515408627929-11669-0/minicluster-data/ts-0-root/wals/dd3f2620f9ac443c963ecd07df725bdb/wal-000000039 (ops 187-191)
I20260812 06:16:59.233613 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: LogGCOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.027s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:16:59.234159 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=3.181125
I20260812 06:16:59.249267 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.015s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4430,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:59.249770 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling UndoDeltaBlockGCOp(dd3f2620f9ac443c963ecd07df725bdb): 508 bytes on disk
I20260812 06:16:59.250188 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: UndoDeltaBlockGCOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:16:59.250785 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=2.188937
I20260812 06:16:59.260314 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3542,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:59.260766 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=1.000000
I20260812 06:16:59.391479 11669 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.995s	user 1.803s	sys 0.181s
I20260812 06:16:59.495280 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: MajorDeltaCompactionOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.234s	user 0.126s	sys 0.108s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123267,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1004,"lbm_read_time_us":16292,"lbm_reads_lt_1ms":871,"lbm_write_time_us":38917,"lbm_writes_lt_1ms":843,"mutex_wait_us":69,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":138,"threads_started":1,"update_count":4000}
I20260812 06:16:59.496366 12071 maintenance_manager.cc:419] P d2ece8234e2a4298a0846474e015a1f2: Scheduling FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb): perf score=10.126437
I20260812 06:16:59.502065 11669 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.110s	user 0.002s	sys 0.000s
I20260812 06:16:59.502573 11669 tablet_server.cc:179] TabletServer@127.11.101.65:0 shutting down...
I20260812 06:16:59.533260 12002 maintenance_manager.cc:643] P d2ece8234e2a4298a0846474e015a1f2: FlushDeltaMemStoresOp(dd3f2620f9ac443c963ecd07df725bdb) complete. Timing: real 0.037s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15967,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:59.533852 11669 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:59.534072 11669 tablet_replica.cc:333] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2: stopping tablet replica
I20260812 06:16:59.534212 11669 raft_consensus.cc:2243] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:59.534406 11669 raft_consensus.cc:2272] T dd3f2620f9ac443c963ecd07df725bdb P d2ece8234e2a4298a0846474e015a1f2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:59.538321 11669 tablet_server.cc:196] TabletServer@127.11.101.65:0 shutdown complete.
I20260812 06:16:59.567127 11669 master.cc:562] Master@127.11.101.126:37995 shutting down...
I20260812 06:16:59.570660 11669 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:59.570853 11669 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:59.570935 11669 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8345b371d6274642b4e19309eaf5554b: stopping tablet replica
I20260812 06:16:59.583330 11669 master.cc:584] Master@127.11.101.126:37995 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5490 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11031 ms total)

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