[==========] 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:20:02.628960   496 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.124.62:45057
I20260812 06:20:02.630162   496 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:20:02.630834   496 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:02.638098   506 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:20:02.638113   508 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:20:02.638170   496 server_base.cc:1061] running on GCE node
W20260812 06:20:02.638432   502 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:20:02.638998   496 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:02.639093   496 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:20:02.639120   496 hybrid_clock.cc:648] HybridClock initialized: now 1786515602639119 us; error 0 us; skew 500 ppm
I20260812 06:20:02.640969   496 webserver.cc:533] Webserver started at http://127.0.124.62:43899/ using document root <none> and password file <none>
I20260812 06:20:02.641538   496 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:02.641602   496 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:02.641788   496 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:02.643406   496 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/master-0-root/instance:
uuid: "161030c601ae4467b40b8c504cbb1bf4"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-z8x9"
I20260812 06:20:02.646893   496 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:20:02.648940   517 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:20:02.650068   496 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:02.650211   496 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/master-0-root
uuid: "161030c601ae4467b40b8c504cbb1bf4"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-z8x9"
I20260812 06:20:02.650345   496 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-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:20:02.682274   496 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:02.682978   496 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:20:02.683173   496 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:02.691128   496 rpc_server.cc:307] RPC server started. Bound to: 127.0.124.62:45057
I20260812 06:20:02.691146   611 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.124.62:45057 every 8 connection(s)
I20260812 06:20:02.693502   612 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:20:02.698993   612 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4: Bootstrap starting.
I20260812 06:20:02.701730   612 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:02.702718   612 log.cc:826] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:02.705683   612 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4: No bootstrap required, opened a new log
I20260812 06:20:02.708652   612 raft_consensus.cc:359] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "161030c601ae4467b40b8c504cbb1bf4" member_type: VOTER }
I20260812 06:20:02.708838   612 raft_consensus.cc:385] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:02.708911   612 raft_consensus.cc:740] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 161030c601ae4467b40b8c504cbb1bf4, State: Initialized, Role: FOLLOWER
I20260812 06:20:02.709585   612 consensus_queue.cc:260] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [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: "161030c601ae4467b40b8c504cbb1bf4" member_type: VOTER }
I20260812 06:20:02.709767   612 raft_consensus.cc:399] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:02.709853   612 raft_consensus.cc:493] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:02.709997   612 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:02.710876   612 raft_consensus.cc:515] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "161030c601ae4467b40b8c504cbb1bf4" member_type: VOTER }
I20260812 06:20:02.711349   612 leader_election.cc:304] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [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: 161030c601ae4467b40b8c504cbb1bf4; no voters: 
I20260812 06:20:02.711704   612 leader_election.cc:290] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:02.711879   616 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:02.712158   616 raft_consensus.cc:697] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [term 1 LEADER]: Becoming Leader. State: Replica: 161030c601ae4467b40b8c504cbb1bf4, State: Running, Role: LEADER
I20260812 06:20:02.712586   616 consensus_queue.cc:237] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [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: "161030c601ae4467b40b8c504cbb1bf4" member_type: VOTER }
I20260812 06:20:02.712847   612 sys_catalog.cc:565] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:02.714767   617 sys_catalog.cc:455] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "161030c601ae4467b40b8c504cbb1bf4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "161030c601ae4467b40b8c504cbb1bf4" member_type: VOTER } }
I20260812 06:20:02.714825   618 sys_catalog.cc:455] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 161030c601ae4467b40b8c504cbb1bf4. Latest consensus state: current_term: 1 leader_uuid: "161030c601ae4467b40b8c504cbb1bf4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "161030c601ae4467b40b8c504cbb1bf4" member_type: VOTER } }
I20260812 06:20:02.714910   617 sys_catalog.cc:458] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:02.714936   618 sys_catalog.cc:458] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:02.715310   633 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:02.718179   633 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:02.718497   496 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:02.723109   633 catalog_manager.cc:1383] Generated new cluster ID: 94aab9a325674257b40d3d9b83efd833
I20260812 06:20:02.723191   633 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:02.745463   633 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:02.746431   633 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:02.751657   633 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4: Generated new TSK 0
I20260812 06:20:02.752321   633 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:02.783691   496 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:02.786809   655 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:20:02.786829   656 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:20:02.787017   496 server_base.cc:1061] running on GCE node
W20260812 06:20:02.786919   660 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:20:02.787360   496 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:02.787429   496 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:20:02.787458   496 hybrid_clock.cc:648] HybridClock initialized: now 1786515602787458 us; error 0 us; skew 500 ppm
I20260812 06:20:02.788571   496 webserver.cc:533] Webserver started at http://127.0.124.1:33883/ using document root <none> and password file <none>
I20260812 06:20:02.788754   496 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:02.788830   496 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:02.788935   496 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:02.789455   496 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/instance:
uuid: "f5372ff1b6624266a8f449bb29f6ff26"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-z8x9"
I20260812 06:20:02.791131   496 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:02.792196   666 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:20:02.792503   496 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:02.792582   496 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root
uuid: "f5372ff1b6624266a8f449bb29f6ff26"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-z8x9"
I20260812 06:20:02.792673   496 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-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:20:02.799707   496 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:02.800153   496 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:02.800614   496 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:02.801590   496 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:02.801645   496 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:02.801715   496 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:02.801757   496 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:02.808866   496 rpc_server.cc:307] RPC server started. Bound to: 127.0.124.1:46769
I20260812 06:20:02.809092   770 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.124.1:46769 every 8 connection(s)
I20260812 06:20:02.824443   774 heartbeater.cc:344] Connected to a master server at 127.0.124.62:45057
I20260812 06:20:02.824771   774 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:02.825385   774 heartbeater.cc:507] Master 127.0.124.62:45057 requested a full tablet report, sending...
I20260812 06:20:02.827090   548 ts_manager.cc:194] Registered new tserver with Master: f5372ff1b6624266a8f449bb29f6ff26 (127.0.124.1:46769)
I20260812 06:20:02.827890   496 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.018214927s
I20260812 06:20:02.828621   548 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54984
I20260812 06:20:02.839974   548 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54986:
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:20:02.855881   721 tablet_service.cc:1511] Processing CreateTablet for tablet 6ee6ebb65409488ead2610efb204c3cd (DEFAULT_TABLE table=heavy-update-compaction-test [id=5e665e136e7e40548f23783548e6474a]), partition=
I20260812 06:20:02.856374   721 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6ee6ebb65409488ead2610efb204c3cd. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:02.859545   792 tablet_bootstrap.cc:492] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Bootstrap starting.
I20260812 06:20:02.860580   792 tablet_bootstrap.cc:654] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:02.861825   792 tablet_bootstrap.cc:492] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: No bootstrap required, opened a new log
I20260812 06:20:02.861925   792 ts_tablet_manager.cc:1403] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:20:02.862871   792 raft_consensus.cc:359] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f5372ff1b6624266a8f449bb29f6ff26" member_type: VOTER last_known_addr { host: "127.0.124.1" port: 46769 } }
I20260812 06:20:02.863071   792 raft_consensus.cc:385] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:02.863132   792 raft_consensus.cc:740] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f5372ff1b6624266a8f449bb29f6ff26, State: Initialized, Role: FOLLOWER
I20260812 06:20:02.863296   792 consensus_queue.cc:260] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [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: "f5372ff1b6624266a8f449bb29f6ff26" member_type: VOTER last_known_addr { host: "127.0.124.1" port: 46769 } }
I20260812 06:20:02.863394   792 raft_consensus.cc:399] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:02.863422   792 raft_consensus.cc:493] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:02.863502   792 raft_consensus.cc:3060] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:02.864316   792 raft_consensus.cc:515] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f5372ff1b6624266a8f449bb29f6ff26" member_type: VOTER last_known_addr { host: "127.0.124.1" port: 46769 } }
I20260812 06:20:02.864472   792 leader_election.cc:304] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [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: f5372ff1b6624266a8f449bb29f6ff26; no voters: 
I20260812 06:20:02.864723   792 leader_election.cc:290] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:02.864874   797 raft_consensus.cc:2804] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:02.865120   792 ts_tablet_manager.cc:1434] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:20:02.865371   774 heartbeater.cc:499] Master 127.0.124.62:45057 was elected leader, sending a full tablet report...
I20260812 06:20:02.865202   797 raft_consensus.cc:697] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [term 1 LEADER]: Becoming Leader. State: Replica: f5372ff1b6624266a8f449bb29f6ff26, State: Running, Role: LEADER
I20260812 06:20:02.865869   797 consensus_queue.cc:237] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [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: "f5372ff1b6624266a8f449bb29f6ff26" member_type: VOTER last_known_addr { host: "127.0.124.1" port: 46769 } }
I20260812 06:20:02.869431   547 catalog_manager.cc:5719] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 reported cstate change: term changed from 0 to 1, leader changed from <none> to f5372ff1b6624266a8f449bb29f6ff26 (127.0.124.1). New cstate: current_term: 1 leader_uuid: "f5372ff1b6624266a8f449bb29f6ff26" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f5372ff1b6624266a8f449bb29f6ff26" member_type: VOTER last_known_addr { host: "127.0.124.1" port: 46769 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:02.939662   496 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.015s	sys 0.016s
I20260812 06:20:03.060482   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushMRSOp(6ee6ebb65409488ead2610efb204c3cd): perf score=15.086190
I20260812 06:20:03.208695   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushMRSOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.148s	user 0.118s	sys 0.016s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":420,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":908,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":32136,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":169,"threads_started":1,"update_count":1050}
I20260812 06:20:03.209842   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling LogGCOp(6ee6ebb65409488ead2610efb204c3cd): free 20290830 bytes of WAL
I20260812 06:20:03.210163   673 log_reader.cc:385] T 6ee6ebb65409488ead2610efb204c3cd: removed 2 log segments from log reader
I20260812 06:20:03.210250   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000001 (ops 1-6)
I20260812 06:20:03.210331   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000002 (ops 7-10)
I20260812 06:20:03.215008   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: LogGCOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:03.215684   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling UndoDeltaBlockGCOp(6ee6ebb65409488ead2610efb204c3cd): 12308959 bytes on disk
I20260812 06:20:03.216562   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: UndoDeltaBlockGCOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4}
I20260812 06:20:03.217089   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:03.231984   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4997,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:03.232554   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:03.355095   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.122s	user 0.093s	sys 0.024s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":612,"lbm_read_time_us":7534,"lbm_reads_lt_1ms":360,"lbm_write_time_us":19687,"lbm_writes_lt_1ms":343,"mutex_wait_us":37,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":7936,"thread_start_us":278,"threads_started":5,"update_count":1500}
I20260812 06:20:03.355784   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:03.405851   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.050s	user 0.033s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17866,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.406376   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:03.417804   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.418329   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:03.560446   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.142s	user 0.109s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":315,"lbm_read_time_us":10134,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26887,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:20:03.561208   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:03.613795   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.052s	user 0.024s	sys 0.024s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":18571,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.615310   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:03.737916   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.122s	user 0.086s	sys 0.036s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528785,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":439,"lbm_read_time_us":9680,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18029,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.738649   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:03.781002   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.042s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17406,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.781638   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:03.798978   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6424,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.799645   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:03.927824   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.128s	user 0.095s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":844,"lbm_read_time_us":8761,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23941,"lbm_writes_lt_1ms":443,"mutex_wait_us":335,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24576,"update_count":2000}
I20260812 06:20:03.928798   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:03.976295   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.047s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17683,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.976824   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:03.988055   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4069,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.988694   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:04.119442   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.131s	user 0.085s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":8186,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27988,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.120105   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:04.170054   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.050s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14799,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:04.170663   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:04.184176   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5284,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.184684   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:04.341017   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.156s	user 0.090s	sys 0.063s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":364,"lbm_read_time_us":13225,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25803,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.341652   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:04.381435   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.040s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17285,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:04.381975   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:04.484329   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.102s	user 0.080s	sys 0.021s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":593,"lbm_read_time_us":5725,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21171,"lbm_writes_lt_1ms":343,"mutex_wait_us":22,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":1500}
I20260812 06:20:04.484987   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:04.532648   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.047s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17877,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:04.533155   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:04.543459   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3916,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.544174   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushMRSOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:04.572223   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushMRSOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.028s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1406,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1367,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":1408}
I20260812 06:20:04.573045   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling LogGCOp(6ee6ebb65409488ead2610efb204c3cd): free 112239306 bytes of WAL
I20260812 06:20:04.573318   673 log_reader.cc:385] T 6ee6ebb65409488ead2610efb204c3cd: removed 11 log segments from log reader
I20260812 06:20:04.573362   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000003 (ops 11-15)
I20260812 06:20:04.573391   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000004 (ops 16-20)
I20260812 06:20:04.573452   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000005 (ops 21-25)
I20260812 06:20:04.573493   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000006 (ops 26-30)
I20260812 06:20:04.573534   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000007 (ops 31-35)
I20260812 06:20:04.573596   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000008 (ops 36-40)
I20260812 06:20:04.573652   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000009 (ops 41-44)
I20260812 06:20:04.573686   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000010 (ops 45-49)
I20260812 06:20:04.573725   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000011 (ops 50-54)
I20260812 06:20:04.573762   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000012 (ops 55-59)
I20260812 06:20:04.573804   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000013 (ops 60-64)
I20260812 06:20:04.598248   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: LogGCOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:20:04.598701   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=3.181125
I20260812 06:20:04.611804   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4553,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:04.612239   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling UndoDeltaBlockGCOp(6ee6ebb65409488ead2610efb204c3cd): 462 bytes on disk
I20260812 06:20:04.612648   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: UndoDeltaBlockGCOp(6ee6ebb65409488ead2610efb204c3cd) 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:20:04.613061   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:04.622778   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3633,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:04.623186   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:04.800477   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.177s	user 0.127s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836360,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":913,"lbm_read_time_us":11022,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36165,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5888,"thread_start_us":168,"threads_started":1,"update_count":3000}
I20260812 06:20:04.801070   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=14.095187
I20260812 06:20:04.848676   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.047s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21183,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.849157   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:04.864675   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.015s	user 0.008s	sys 0.004s 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:20:04.865478   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:05.035046   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.169s	user 0.124s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":800,"lbm_read_time_us":11962,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31051,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:20:05.038390   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=13.103000
I20260812 06:20:05.084196   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.046s	user 0.026s	sys 0.016s Metrics: {"bytes_written":14604840,"delete_count":0,"lbm_write_time_us":19974,"lbm_writes_lt_1ms":359,"reinsert_count":0,"update_count":1780}
I20260812 06:20:05.084695   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:05.097893   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.013s	user 0.007s	sys 0.000s Metrics: {"bytes_written":1805252,"delete_count":0,"lbm_write_time_us":2689,"lbm_writes_lt_1ms":47,"reinsert_count":0,"update_count":220}
I20260812 06:20:05.098506   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:05.238193   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.139s	user 0.096s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631256,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1275,"lbm_read_time_us":8661,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22507,"lbm_writes_lt_1ms":443,"mutex_wait_us":334,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:20:05.238955   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=11.118625
I20260812 06:20:05.274139   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.035s	user 0.010s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15584,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:05.274691   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:05.286496   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3989,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":450}
I20260812 06:20:05.287078   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:05.422703   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.135s	user 0.111s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":169,"lbm_read_time_us":8490,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26887,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":60544,"update_count":2000}
I20260812 06:20:05.423573   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:05.470844   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.047s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21102,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:05.471450   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:05.488910   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6613,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.489521   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:05.623220   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.133s	user 0.100s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":10629,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27343,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2000}
I20260812 06:20:05.625634   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:05.670506   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.045s	user 0.035s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20412,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:05.671088   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:05.684355   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5173,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.684840   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:05.822007   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.137s	user 0.121s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":265,"lbm_read_time_us":9771,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29389,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:05.823089   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:05.874119   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.051s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19158,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:05.874719   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:05.887176   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.887807   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:06.037402   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.148s	user 0.115s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1337,"lbm_read_time_us":12088,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25637,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:06.038160   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:06.080893   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.043s	user 0.026s	sys 0.013s Metrics: {"bytes_written":12348515,"delete_count":0,"lbm_write_time_us":18569,"lbm_writes_lt_1ms":304,"reinsert_count":0,"update_count":1505}
I20260812 06:20:06.081521   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:06.097960   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.016s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":6462,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:20:06.098461   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushMRSOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:06.132427   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushMRSOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.034s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":104,"dirs.run_cpu_time_us":287,"dirs.run_wall_time_us":1607,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2155,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:06.133430   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling LogGCOp(6ee6ebb65409488ead2610efb204c3cd): free 129773565 bytes of WAL
I20260812 06:20:06.133976   673 log_reader.cc:385] T 6ee6ebb65409488ead2610efb204c3cd: removed 13 log segments from log reader
I20260812 06:20:06.134102   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000014 (ops 65-69)
I20260812 06:20:06.134167   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000015 (ops 70-74)
I20260812 06:20:06.134227   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000016 (ops 75-79)
I20260812 06:20:06.134272   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000017 (ops 80-84)
I20260812 06:20:06.134311   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000018 (ops 85-88)
I20260812 06:20:06.134348   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000019 (ops 89-93)
I20260812 06:20:06.134387   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000020 (ops 94-98)
I20260812 06:20:06.134426   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000021 (ops 99-103)
I20260812 06:20:06.134469   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000022 (ops 104-108)
I20260812 06:20:06.134660   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000023 (ops 109-113)
I20260812 06:20:06.134771   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000024 (ops 114-118)
I20260812 06:20:06.134819   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000025 (ops 119-123)
I20260812 06:20:06.134858   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000026 (ops 124-128)
I20260812 06:20:06.166679   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: LogGCOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:20:06.167542   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling UndoDeltaBlockGCOp(6ee6ebb65409488ead2610efb204c3cd): 483 bytes on disk
I20260812 06:20:06.168010   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: UndoDeltaBlockGCOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:20:06.168843   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=6.157687
I20260812 06:20:06.198495   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.029s	user 0.014s	sys 0.011s Metrics: {"bytes_written":8082006,"delete_count":0,"lbm_write_time_us":10075,"lbm_writes_lt_1ms":200,"reinsert_count":0,"update_count":985}
I20260812 06:20:06.199041   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:06.393460   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.194s	user 0.158s	sys 0.036s Metrics: {"cfile_cache_miss":630,"cfile_cache_miss_bytes":28713184,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":482,"lbm_read_time_us":15450,"lbm_reads_lt_1ms":662,"lbm_write_time_us":34264,"lbm_writes_lt_1ms":640,"mutex_wait_us":28,"peak_mem_usage":74378983,"reinsert_count":0,"spinlock_wait_cycles":70400,"thread_start_us":82,"threads_started":1,"update_count":2985}
I20260812 06:20:06.394052   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=15.087375
I20260812 06:20:06.454299   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.060s	user 0.032s	sys 0.027s Metrics: {"bytes_written":16532978,"delete_count":0,"lbm_write_time_us":22960,"lbm_writes_lt_1ms":406,"reinsert_count":0,"update_count":2015}
I20260812 06:20:06.454927   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:06.465653   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4016,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.466161   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:06.645092   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.179s	user 0.103s	sys 0.073s Metrics: {"cfile_cache_miss":535,"cfile_cache_miss_bytes":24856800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1052,"lbm_read_time_us":13948,"lbm_reads_lt_1ms":575,"lbm_write_time_us":31568,"lbm_writes_lt_1ms":546,"mutex_wait_us":337,"peak_mem_usage":63239005,"reinsert_count":0,"spinlock_wait_cycles":31232,"update_count":2515}
I20260812 06:20:06.645895   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=11.118625
I20260812 06:20:06.684013   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.038s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16565,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:06.684692   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:06.702126   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.017s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5066,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:06.702708   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:06.837999   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.135s	user 0.102s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":282,"lbm_read_time_us":7624,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26595,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:20:06.838634   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=11.118625
I20260812 06:20:06.878043   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.039s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15882,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:06.878526   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:06.891924   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5106,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:06.892436   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:07.042184   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.150s	user 0.120s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1045,"lbm_read_time_us":9498,"lbm_reads_lt_1ms":464,"lbm_write_time_us":33452,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:07.043097   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:07.080268   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.037s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16831,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:07.080756   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:07.093358   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4166,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.094007   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:07.220950   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.127s	user 0.099s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":384,"lbm_read_time_us":8893,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25130,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:20:07.221671   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:07.272857   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.051s	user 0.028s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19096,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:07.273608   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:07.290737   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6711,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.291528   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:07.439388   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.148s	user 0.111s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1025,"lbm_read_time_us":11675,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24527,"lbm_writes_lt_1ms":443,"mutex_wait_us":340,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:20:07.440166   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:07.486896   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.047s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16402,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:07.487485   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:07.499804   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4438,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.500543   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:07.633297   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.133s	user 0.102s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1249,"lbm_read_time_us":10237,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24684,"lbm_writes_lt_1ms":443,"mutex_wait_us":335,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:20:07.634106   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=10.126437
I20260812 06:20:07.672569   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.038s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15944,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:07.673085   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:07.684953   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4112,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.685516   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushMRSOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:07.714083   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushMRSOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":288,"dirs.run_wall_time_us":1622,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1736,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:07.714934   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling LogGCOp(6ee6ebb65409488ead2610efb204c3cd): free 132118539 bytes of WAL
I20260812 06:20:07.715214   673 log_reader.cc:385] T 6ee6ebb65409488ead2610efb204c3cd: removed 13 log segments from log reader
I20260812 06:20:07.715279   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000027 (ops 129-132)
I20260812 06:20:07.715320   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000028 (ops 133-137)
I20260812 06:20:07.715356   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000029 (ops 138-142)
I20260812 06:20:07.715385   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000030 (ops 143-146)
I20260812 06:20:07.715417   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000031 (ops 147-151)
I20260812 06:20:07.715451   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000032 (ops 152-156)
I20260812 06:20:07.715477   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000033 (ops 157-161)
I20260812 06:20:07.715505   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000034 (ops 162-166)
I20260812 06:20:07.715533   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000035 (ops 167-171)
I20260812 06:20:07.715564   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000036 (ops 172-176)
I20260812 06:20:07.715598   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000037 (ops 177-180)
I20260812 06:20:07.715629   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000038 (ops 181-185)
I20260812 06:20:07.715669   673 log.cc:1079] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515602618035-496-0/minicluster-data/ts-0-root/wals/6ee6ebb65409488ead2610efb204c3cd/wal-000000039 (ops 186-190)
I20260812 06:20:07.748852   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: LogGCOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.034s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:07.749434   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:07.771345   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.022s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6474,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.771852   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling UndoDeltaBlockGCOp(6ee6ebb65409488ead2610efb204c3cd): 482 bytes on disk
I20260812 06:20:07.772262   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: UndoDeltaBlockGCOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:20:07.772775   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=2.188937
I20260812 06:20:07.787319   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4764,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.787890   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd): perf score=1.000000
I20260812 06:20:07.970130   496 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.030s	user 1.891s	sys 0.117s
I20260812 06:20:07.973251   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: MajorDeltaCompactionOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.185s	user 0.143s	sys 0.033s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":776,"lbm_read_time_us":11771,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39072,"lbm_writes_lt_1ms":643,"mutex_wait_us":571,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":101,"threads_started":1,"update_count":3000}
I20260812 06:20:07.974475   775 maintenance_manager.cc:419] P f5372ff1b6624266a8f449bb29f6ff26: Scheduling FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd): perf score=14.095187
I20260812 06:20:07.998768   496 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.028s	user 0.002s	sys 0.000s
I20260812 06:20:07.999451   496 tablet_server.cc:179] TabletServer@127.0.124.1:0 shutting down...
I20260812 06:20:08.025086   673 maintenance_manager.cc:643] P f5372ff1b6624266a8f449bb29f6ff26: FlushDeltaMemStoresOp(6ee6ebb65409488ead2610efb204c3cd) complete. Timing: real 0.050s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22537,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.025872   496 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:08.026363   496 tablet_replica.cc:333] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26: stopping tablet replica
I20260812 06:20:08.026625   496 raft_consensus.cc:2243] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:08.026898   496 raft_consensus.cc:2272] T 6ee6ebb65409488ead2610efb204c3cd P f5372ff1b6624266a8f449bb29f6ff26 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:08.031662   496 tablet_server.cc:196] TabletServer@127.0.124.1:0 shutdown complete.
I20260812 06:20:08.036926   496 master.cc:562] Master@127.0.124.62:45057 shutting down...
I20260812 06:20:08.042162   496 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:08.042443   496 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:08.042533   496 tablet_replica.cc:333] T 00000000000000000000000000000000 P 161030c601ae4467b40b8c504cbb1bf4: stopping tablet replica
I20260812 06:20:08.055956   496 master.cc:584] Master@127.0.124.62:45057 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5521 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:08.149892   496 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.124.62:46747
I20260812 06:20:08.150315   496 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:08.153326   496 server_base.cc:1061] running on GCE node
W20260812 06:20:08.153399   836 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:20:08.153460   834 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:20:08.153515   833 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:20:08.153757   496 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:08.153806   496 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:20:08.153821   496 hybrid_clock.cc:648] HybridClock initialized: now 1786515608153821 us; error 0 us; skew 500 ppm
I20260812 06:20:08.154826   496 webserver.cc:533] Webserver started at http://127.0.124.62:33003/ using document root <none> and password file <none>
I20260812 06:20:08.154981   496 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:08.155028   496 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:08.155097   496 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:08.155460   496 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/master-0-root/instance:
uuid: "0a935177e0d1491cac0d86aec659b737"
format_stamp: "Formatted at 2026-08-12 06:20:08 on dist-test-slave-z8x9"
I20260812 06:20:08.157086   496 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:08.158444   844 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:20:08.158789   496 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:08.158880   496 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/master-0-root
uuid: "0a935177e0d1491cac0d86aec659b737"
format_stamp: "Formatted at 2026-08-12 06:20:08 on dist-test-slave-z8x9"
I20260812 06:20:08.158938   496 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-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:20:08.171314   496 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:08.171754   496 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:08.176296   496 rpc_server.cc:307] RPC server started. Bound to: 127.0.124.62:46747
I20260812 06:20:08.178476   926 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.124.62:46747 every 8 connection(s)
I20260812 06:20:08.179239   927 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:20:08.196123   927 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737: Bootstrap starting.
I20260812 06:20:08.197263   927 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:08.198997   927 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737: No bootstrap required, opened a new log
I20260812 06:20:08.199692   927 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a935177e0d1491cac0d86aec659b737" member_type: VOTER }
I20260812 06:20:08.200016   927 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:08.200040   927 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0a935177e0d1491cac0d86aec659b737, State: Initialized, Role: FOLLOWER
I20260812 06:20:08.200253   927 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [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: "0a935177e0d1491cac0d86aec659b737" member_type: VOTER }
I20260812 06:20:08.200340   927 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:08.200364   927 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:08.200395   927 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:08.201395   927 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a935177e0d1491cac0d86aec659b737" member_type: VOTER }
I20260812 06:20:08.201540   927 leader_election.cc:304] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [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: 0a935177e0d1491cac0d86aec659b737; no voters: 
I20260812 06:20:08.201800   927 leader_election.cc:290] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:08.202034   931 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:08.202279   931 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [term 1 LEADER]: Becoming Leader. State: Replica: 0a935177e0d1491cac0d86aec659b737, State: Running, Role: LEADER
I20260812 06:20:08.202356   927 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:08.202422   931 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [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: "0a935177e0d1491cac0d86aec659b737" member_type: VOTER }
I20260812 06:20:08.202960   932 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0a935177e0d1491cac0d86aec659b737" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a935177e0d1491cac0d86aec659b737" member_type: VOTER } }
I20260812 06:20:08.203011   935 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0a935177e0d1491cac0d86aec659b737. Latest consensus state: current_term: 1 leader_uuid: "0a935177e0d1491cac0d86aec659b737" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a935177e0d1491cac0d86aec659b737" member_type: VOTER } }
I20260812 06:20:08.203066   932 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:08.203094   935 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:08.203354   948 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:08.204332   948 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:08.204638   496 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:08.206627   948 catalog_manager.cc:1383] Generated new cluster ID: 1bce997a5dca441c839826a741230c59
I20260812 06:20:08.206703   948 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:08.221011   948 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:08.221730   948 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:08.229386   948 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737: Generated new TSK 0
I20260812 06:20:08.229676   948 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:08.237967   496 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:20:08.241066   496 server_base.cc:1061] running on GCE node
W20260812 06:20:08.241042   971 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:20:08.241050   968 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:20:08.241041   967 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:20:08.241627   496 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:08.241695   496 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:20:08.241722   496 hybrid_clock.cc:648] HybridClock initialized: now 1786515608241722 us; error 0 us; skew 500 ppm
I20260812 06:20:08.242736   496 webserver.cc:533] Webserver started at http://127.0.124.1:33593/ using document root <none> and password file <none>
I20260812 06:20:08.242955   496 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:08.243034   496 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:08.243124   496 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:08.243566   496 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/instance:
uuid: "c225ed35683346239dfe4acbd8a7ab3d"
format_stamp: "Formatted at 2026-08-12 06:20:08 on dist-test-slave-z8x9"
I20260812 06:20:08.245949   496 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:08.247191   978 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:20:08.247625   496 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:08.247740   496 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root
uuid: "c225ed35683346239dfe4acbd8a7ab3d"
format_stamp: "Formatted at 2026-08-12 06:20:08 on dist-test-slave-z8x9"
I20260812 06:20:08.247843   496 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-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:20:08.256735   496 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:08.257220   496 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:08.257568   496 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:08.258069   496 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:08.258133   496 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:08.258204   496 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:08.258256   496 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:08.262745   496 rpc_server.cc:307] RPC server started. Bound to: 127.0.124.1:41393
I20260812 06:20:08.262781  1073 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.124.1:41393 every 8 connection(s)
I20260812 06:20:08.271273  1074 heartbeater.cc:344] Connected to a master server at 127.0.124.62:46747
I20260812 06:20:08.271432  1074 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:08.271660  1074 heartbeater.cc:507] Master 127.0.124.62:46747 requested a full tablet report, sending...
I20260812 06:20:08.272469   868 ts_manager.cc:194] Registered new tserver with Master: c225ed35683346239dfe4acbd8a7ab3d (127.0.124.1:41393)
I20260812 06:20:08.273353   868 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35664
I20260812 06:20:08.273432   496 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010207986s
I20260812 06:20:08.283384   868 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35672:
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:20:08.293886  1024 tablet_service.cc:1511] Processing CreateTablet for tablet 738fbd0812bd41349cec03967ade240c (DEFAULT_TABLE table=heavy-update-compaction-test [id=431db599fcc4475f9c208529c3784191]), partition=
I20260812 06:20:08.294215  1024 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 738fbd0812bd41349cec03967ade240c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:08.296389  1094 tablet_bootstrap.cc:492] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Bootstrap starting.
I20260812 06:20:08.297286  1094 tablet_bootstrap.cc:654] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:08.298411  1094 tablet_bootstrap.cc:492] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: No bootstrap required, opened a new log
I20260812 06:20:08.298486  1094 ts_tablet_manager.cc:1403] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:20:08.298933  1094 raft_consensus.cc:359] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c225ed35683346239dfe4acbd8a7ab3d" member_type: VOTER last_known_addr { host: "127.0.124.1" port: 41393 } }
I20260812 06:20:08.299024  1094 raft_consensus.cc:385] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:08.299046  1094 raft_consensus.cc:740] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c225ed35683346239dfe4acbd8a7ab3d, State: Initialized, Role: FOLLOWER
I20260812 06:20:08.299206  1094 consensus_queue.cc:260] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [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: "c225ed35683346239dfe4acbd8a7ab3d" member_type: VOTER last_known_addr { host: "127.0.124.1" port: 41393 } }
I20260812 06:20:08.299322  1094 raft_consensus.cc:399] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:08.299378  1094 raft_consensus.cc:493] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:08.299434  1094 raft_consensus.cc:3060] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:08.300295  1094 raft_consensus.cc:515] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c225ed35683346239dfe4acbd8a7ab3d" member_type: VOTER last_known_addr { host: "127.0.124.1" port: 41393 } }
I20260812 06:20:08.300426  1094 leader_election.cc:304] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [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: c225ed35683346239dfe4acbd8a7ab3d; no voters: 
I20260812 06:20:08.300583  1094 leader_election.cc:290] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:08.300804  1098 raft_consensus.cc:2804] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:08.300891  1094 ts_tablet_manager.cc:1434] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:20:08.300926  1098 raft_consensus.cc:697] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [term 1 LEADER]: Becoming Leader. State: Replica: c225ed35683346239dfe4acbd8a7ab3d, State: Running, Role: LEADER
I20260812 06:20:08.300956  1074 heartbeater.cc:499] Master 127.0.124.62:46747 was elected leader, sending a full tablet report...
I20260812 06:20:08.301111  1098 consensus_queue.cc:237] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [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: "c225ed35683346239dfe4acbd8a7ab3d" member_type: VOTER last_known_addr { host: "127.0.124.1" port: 41393 } }
I20260812 06:20:08.302603   868 catalog_manager.cc:5719] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d reported cstate change: term changed from 0 to 1, leader changed from <none> to c225ed35683346239dfe4acbd8a7ab3d (127.0.124.1). New cstate: current_term: 1 leader_uuid: "c225ed35683346239dfe4acbd8a7ab3d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c225ed35683346239dfe4acbd8a7ab3d" member_type: VOTER last_known_addr { host: "127.0.124.1" port: 41393 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:08.363327   496 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.009s	sys 0.013s
I20260812 06:20:08.513864  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushMRSOp(738fbd0812bd41349cec03967ade240c): perf score=19.054940
I20260812 06:20:08.675302   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushMRSOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.161s	user 0.114s	sys 0.044s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":963,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44234,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:08.676007  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling LogGCOp(738fbd0812bd41349cec03967ade240c): free 20743880 bytes of WAL
I20260812 06:20:08.676271   985 log_reader.cc:385] T 738fbd0812bd41349cec03967ade240c: removed 2 log segments from log reader
I20260812 06:20:08.676319   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000001 (ops 1-6)
I20260812 06:20:08.676350   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000002 (ops 7-11)
I20260812 06:20:08.680559   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: LogGCOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:08.681090  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:08.698691   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.017s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.699147  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:08.857420   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.158s	user 0.107s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1109,"lbm_read_time_us":10041,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26701,"lbm_writes_lt_1ms":443,"mutex_wait_us":154,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"thread_start_us":337,"threads_started":5,"update_count":2000}
I20260812 06:20:08.858107  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=14.095187
I20260812 06:20:08.912194   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.054s	user 0.025s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20757,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.912968  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:08.925328   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4491,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.925796  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:09.087591   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.162s	user 0.115s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":341,"lbm_read_time_us":9746,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34933,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:20:09.088181  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling UndoDeltaBlockGCOp(738fbd0812bd41349cec03967ade240c): 16411392 bytes on disk
I20260812 06:20:09.088719   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: UndoDeltaBlockGCOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:20:09.089349  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=11.118625
I20260812 06:20:09.129280   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.040s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15688,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:09.129824  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:09.144222   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5754,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:09.144702  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:09.269635   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.125s	user 0.101s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":153,"lbm_read_time_us":9557,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23610,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:20:09.270346  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=10.126437
I20260812 06:20:09.323426   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.053s	user 0.021s	sys 0.030s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20751,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:09.323990  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:09.334764   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4206,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.335232  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:09.497033   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.162s	user 0.090s	sys 0.069s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":328,"lbm_read_time_us":11196,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28331,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:09.498121  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=10.126437
I20260812 06:20:09.541846   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.043s	user 0.022s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17159,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:09.542397  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:09.554718   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4293,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.555224  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:09.684741   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.129s	user 0.113s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":388,"lbm_read_time_us":10015,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23836,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:20:09.685364  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=10.126437
I20260812 06:20:09.735033   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.049s	user 0.020s	sys 0.021s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18952,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:09.735637  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:09.746831   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.747308  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:09.879077   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.132s	user 0.103s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":344,"lbm_read_time_us":9492,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26139,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":97920,"update_count":2000}
I20260812 06:20:09.879644  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=10.126437
I20260812 06:20:09.932389   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.053s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16036,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:09.932935  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:09.944909   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4616,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.945621  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushMRSOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:09.986440   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushMRSOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.041s	user 0.039s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":125,"dirs.run_cpu_time_us":377,"dirs.run_wall_time_us":2738,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2217,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:09.987249  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling LogGCOp(738fbd0812bd41349cec03967ade240c): free 120553376 bytes of WAL
I20260812 06:20:09.987552   985 log_reader.cc:385] T 738fbd0812bd41349cec03967ade240c: removed 12 log segments from log reader
I20260812 06:20:09.987629   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000003 (ops 12-16)
I20260812 06:20:09.987670   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000004 (ops 17-21)
I20260812 06:20:09.987700   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000005 (ops 22-26)
I20260812 06:20:09.987727   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000006 (ops 27-31)
I20260812 06:20:09.987751   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000007 (ops 32-36)
I20260812 06:20:09.987783   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000008 (ops 37-40)
I20260812 06:20:09.987807   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000009 (ops 41-45)
I20260812 06:20:09.987828   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000010 (ops 46-50)
I20260812 06:20:09.987850   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000011 (ops 51-54)
I20260812 06:20:09.988018   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000012 (ops 55-59)
I20260812 06:20:09.988054   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000013 (ops 60-64)
I20260812 06:20:09.988077   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000014 (ops 65-69)
I20260812 06:20:10.019589   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: LogGCOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:10.020128  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=3.181125
I20260812 06:20:10.032189   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4800074,"delete_count":0,"lbm_write_time_us":4913,"lbm_writes_lt_1ms":120,"reinsert_count":0,"update_count":585}
I20260812 06:20:10.032688  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:10.043277   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3405230,"delete_count":0,"lbm_write_time_us":3494,"lbm_writes_lt_1ms":86,"reinsert_count":0,"update_count":415}
I20260812 06:20:10.044226  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling UndoDeltaBlockGCOp(738fbd0812bd41349cec03967ade240c): 463 bytes on disk
I20260812 06:20:10.045460   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: UndoDeltaBlockGCOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":144,"lbm_reads_lt_1ms":4}
I20260812 06:20:10.046433  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:10.260586   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.214s	user 0.158s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":837,"lbm_read_time_us":15974,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39709,"lbm_writes_lt_1ms":643,"mutex_wait_us":274,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5888,"thread_start_us":94,"threads_started":1,"update_count":3000}
I20260812 06:20:10.261538  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=14.095187
I20260812 06:20:10.328790   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.067s	user 0.041s	sys 0.016s Metrics: {"bytes_written":16409908,"delete_count":0,"lbm_write_time_us":26671,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:10.329452  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:10.344027   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.344686  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:10.522315   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.177s	user 0.130s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774695,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":319,"lbm_read_time_us":11013,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36871,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":69248,"update_count":2500}
I20260812 06:20:10.523245  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=12.110812
I20260812 06:20:10.566187   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.043s	user 0.041s	sys 0.000s Metrics: {"bytes_written":13579241,"delete_count":0,"lbm_write_time_us":17537,"lbm_writes_lt_1ms":334,"reinsert_count":0,"update_count":1655}
I20260812 06:20:10.567015  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=1.196750
I20260812 06:20:10.582366   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.015s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":3317,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:20:10.582960  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:10.747233   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.164s	user 0.107s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672249,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":255,"lbm_read_time_us":10787,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25723,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:20:10.747750  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=14.095187
I20260812 06:20:10.797127   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.049s	user 0.030s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22268,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:10.797688  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:10.821506   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.024s	user 0.007s	sys 0.017s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4915,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.822209  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:11.008184   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.186s	user 0.129s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":426,"lbm_read_time_us":14414,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31380,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:11.008864  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=14.095187
I20260812 06:20:11.064985   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.056s	user 0.019s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22784,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:11.065528  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:11.078634   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.013s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4832,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.079269  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:11.263461   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.184s	user 0.110s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":276,"lbm_read_time_us":10056,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33090,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:20:11.264267  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=11.118625
I20260812 06:20:11.302120   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.038s	user 0.010s	sys 0.027s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14562,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:11.302894  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:11.327759   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.025s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4763,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:11.328269  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:11.338824   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.339444  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:11.512122   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.172s	user 0.127s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":716,"lbm_read_time_us":12068,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31715,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:20:11.512781  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=14.095187
I20260812 06:20:11.571946   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.059s	user 0.035s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":28672,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:11.572508  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:11.584714   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4549,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.585259  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushMRSOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:11.618417   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushMRSOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.033s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1472,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1521,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:11.619199  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling LogGCOp(738fbd0812bd41349cec03967ade240c): free 120553396 bytes of WAL
I20260812 06:20:11.619481   985 log_reader.cc:385] T 738fbd0812bd41349cec03967ade240c: removed 12 log segments from log reader
I20260812 06:20:11.619554   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000015 (ops 70-74)
I20260812 06:20:11.619609   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000016 (ops 75-78)
I20260812 06:20:11.619776   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000017 (ops 79-83)
I20260812 06:20:11.619827   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000018 (ops 84-88)
I20260812 06:20:11.619884   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000019 (ops 89-92)
I20260812 06:20:11.619921   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000020 (ops 93-97)
I20260812 06:20:11.619959   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000021 (ops 98-102)
I20260812 06:20:11.619995   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000022 (ops 103-107)
I20260812 06:20:11.620031   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000023 (ops 108-112)
I20260812 06:20:11.620069   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000024 (ops 113-117)
I20260812 06:20:11.620106   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000025 (ops 118-122)
I20260812 06:20:11.620143   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000026 (ops 123-127)
I20260812 06:20:11.649609   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: LogGCOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:11.650456  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=4.173312
I20260812 06:20:11.675294   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.025s	user 0.004s	sys 0.019s Metrics: {"bytes_written":5292365,"delete_count":0,"lbm_write_time_us":5900,"lbm_writes_lt_1ms":132,"reinsert_count":0,"update_count":645}
I20260812 06:20:11.675835  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling LogGCOp(738fbd0812bd41349cec03967ade240c): free 12017949 bytes of WAL
I20260812 06:20:11.676054   985 log_reader.cc:385] T 738fbd0812bd41349cec03967ade240c: removed 1 log segments from log reader
I20260812 06:20:11.676096   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000027 (ops 128-132)
I20260812 06:20:11.678540   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: LogGCOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:11.678833  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=1.196750
I20260812 06:20:11.686868   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.008s	user 0.002s	sys 0.004s Metrics: {"bytes_written":2912930,"delete_count":0,"lbm_write_time_us":2919,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:20:11.687286  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:11.930686   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.243s	user 0.151s	sys 0.080s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":413,"lbm_read_time_us":16848,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41182,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:20:11.931366  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling UndoDeltaBlockGCOp(738fbd0812bd41349cec03967ade240c): 481 bytes on disk
I20260812 06:20:11.932478   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: UndoDeltaBlockGCOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:20:11.933058  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=18.063937
I20260812 06:20:12.011405   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.078s	user 0.042s	sys 0.021s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":29938,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:12.012224  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:12.023020   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.023880  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:12.262794   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.239s	user 0.150s	sys 0.081s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1545,"lbm_read_time_us":16131,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38109,"lbm_writes_lt_1ms":643,"mutex_wait_us":599,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":3000}
I20260812 06:20:12.263718  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=16.079562
I20260812 06:20:12.326793   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.063s	user 0.023s	sys 0.036s Metrics: {"bytes_written":18173941,"delete_count":0,"lbm_write_time_us":26299,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":445,"reinsert_count":0,"update_count":2215}
I20260812 06:20:12.327627  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=1.196750
I20260812 06:20:12.344295   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":2748834,"delete_count":0,"lbm_write_time_us":4463,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:20:12.344918  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:12.354830   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3593,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:12.355412  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:12.562100   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.207s	user 0.123s	sys 0.083s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877180,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":283,"lbm_read_time_us":13316,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33514,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:20:12.563014  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=14.095187
I20260812 06:20:12.615386   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.052s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23178,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:12.616011  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:12.627519   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.628041  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:12.837303   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.209s	user 0.144s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":307,"lbm_read_time_us":13171,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35461,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":28032,"update_count":2500}
I20260812 06:20:12.837868  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=14.095187
I20260812 06:20:12.901510   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.063s	user 0.042s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21862,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:12.902156  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:12.913393   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4306,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.913859  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:13.110603   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.197s	user 0.144s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":324,"lbm_read_time_us":14277,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34238,"lbm_writes_lt_1ms":543,"mutex_wait_us":90,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:20:13.111742  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=10.126437
I20260812 06:20:13.152459   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.040s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17657,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:13.153131  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:13.165427   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.166046  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushMRSOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:13.211804   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushMRSOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.046s	user 0.038s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":292,"dirs.run_wall_time_us":1623,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1757,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:13.212811  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling LogGCOp(738fbd0812bd41349cec03967ade240c): free 112692573 bytes of WAL
I20260812 06:20:13.213102   985 log_reader.cc:385] T 738fbd0812bd41349cec03967ade240c: removed 11 log segments from log reader
I20260812 06:20:13.213150   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000028 (ops 133-137)
I20260812 06:20:13.213243   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000029 (ops 138-142)
I20260812 06:20:13.213294   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000030 (ops 143-147)
I20260812 06:20:13.213330   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000031 (ops 148-152)
I20260812 06:20:13.213374   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000032 (ops 153-157)
I20260812 06:20:13.213565   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000033 (ops 158-162)
I20260812 06:20:13.213686   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000034 (ops 163-167)
I20260812 06:20:13.213712   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000035 (ops 168-172)
I20260812 06:20:13.213757   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000036 (ops 173-177)
I20260812 06:20:13.213804   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000037 (ops 178-182)
I20260812 06:20:13.213830   985 log.cc:1079] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: Deleting log segment in path: /tmp/dist-test-taskbIlxDs/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515602618035-496-0/minicluster-data/ts-0-root/wals/738fbd0812bd41349cec03967ade240c/wal-000000038 (ops 183-187)
I20260812 06:20:13.241906   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: LogGCOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:20:13.242758  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:13.270357   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.027s	user 0.004s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.271101  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling UndoDeltaBlockGCOp(738fbd0812bd41349cec03967ade240c): 448 bytes on disk
I20260812 06:20:13.271909   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: UndoDeltaBlockGCOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:20:13.272584  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:13.283490   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.284186  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:13.492072   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.208s	user 0.148s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":262,"lbm_read_time_us":14172,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36679,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22400,"thread_start_us":99,"threads_started":1,"update_count":3000}
I20260812 06:20:13.492806  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=14.095187
I20260812 06:20:13.548645   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.056s	user 0.023s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22626,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:20:13.549469  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c): perf score=2.188937
I20260812 06:20:13.566860   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: FlushDeltaMemStoresOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6674,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.567479  1075 maintenance_manager.cc:419] P c225ed35683346239dfe4acbd8a7ab3d: Scheduling MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c): perf score=1.000000
I20260812 06:20:13.610528   496 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.247s	user 1.917s	sys 0.145s
I20260812 06:20:13.674366   496 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.063s	user 0.004s	sys 0.000s
I20260812 06:20:13.675015   496 tablet_server.cc:179] TabletServer@127.0.124.1:0 shutting down...
I20260812 06:20:13.720642   985 maintenance_manager.cc:643] P c225ed35683346239dfe4acbd8a7ab3d: MajorDeltaCompactionOp(738fbd0812bd41349cec03967ade240c) complete. Timing: real 0.153s	user 0.093s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":391,"lbm_read_time_us":11800,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27126,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2500}
I20260812 06:20:13.721451   496 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:13.721760   496 tablet_replica.cc:333] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d: stopping tablet replica
I20260812 06:20:13.721877   496 raft_consensus.cc:2243] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:13.722008   496 raft_consensus.cc:2272] T 738fbd0812bd41349cec03967ade240c P c225ed35683346239dfe4acbd8a7ab3d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:13.727021   496 tablet_server.cc:196] TabletServer@127.0.124.1:0 shutdown complete.
I20260812 06:20:13.767120   496 master.cc:562] Master@127.0.124.62:46747 shutting down...
I20260812 06:20:13.771099   496 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:13.771274   496 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:13.771325   496 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0a935177e0d1491cac0d86aec659b737: stopping tablet replica
I20260812 06:20:13.783870   496 master.cc:584] Master@127.0.124.62:46747 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5726 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11248 ms total)

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