[==========] 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:18:55.671828   348 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.87.62:42625
I20260812 06:18:55.672920   348 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:18:55.673555   348 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:55.680723   356 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:18:55.680780   348 server_base.cc:1061] running on GCE node
W20260812 06:18:55.680727   354 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:18:55.681008   353 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:18:55.681524   348 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:55.681656   348 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:18:55.681712   348 hybrid_clock.cc:648] HybridClock initialized: now 1786515535681709 us; error 0 us; skew 500 ppm
I20260812 06:18:55.683691   348 webserver.cc:533] Webserver started at http://127.0.87.62:40887/ using document root <none> and password file <none>
I20260812 06:18:55.684294   348 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:55.684388   348 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:55.684696   348 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:55.686414   348 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/master-0-root/instance:
uuid: "bbfb0b4609b4466995d5b7e2ff2def5e"
format_stamp: "Formatted at 2026-08-12 06:18:55 on dist-test-slave-65mx"
I20260812 06:18:55.690212   348 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.002s
I20260812 06:18:55.692466   363 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:18:55.693645   348 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:18:55.693799   348 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/master-0-root
uuid: "bbfb0b4609b4466995d5b7e2ff2def5e"
format_stamp: "Formatted at 2026-08-12 06:18:55 on dist-test-slave-65mx"
I20260812 06:18:55.693920   348 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-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:18:55.720343   348 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:55.721122   348 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:18:55.721320   348 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:55.729307   348 rpc_server.cc:307] RPC server started. Bound to: 127.0.87.62:42625
I20260812 06:18:55.729336   420 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.87.62:42625 every 8 connection(s)
I20260812 06:18:55.731793   422 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:18:55.738018   422 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e: Bootstrap starting.
I20260812 06:18:55.740631   422 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:55.741649   422 log.cc:826] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:55.743579   422 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e: No bootstrap required, opened a new log
I20260812 06:18:55.746595   422 raft_consensus.cc:359] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbfb0b4609b4466995d5b7e2ff2def5e" member_type: VOTER }
I20260812 06:18:55.746779   422 raft_consensus.cc:385] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:55.746822   422 raft_consensus.cc:740] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bbfb0b4609b4466995d5b7e2ff2def5e, State: Initialized, Role: FOLLOWER
I20260812 06:18:55.747463   422 consensus_queue.cc:260] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [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: "bbfb0b4609b4466995d5b7e2ff2def5e" member_type: VOTER }
I20260812 06:18:55.747609   422 raft_consensus.cc:399] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:55.747666   422 raft_consensus.cc:493] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:55.747754   422 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:55.748536   422 raft_consensus.cc:515] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbfb0b4609b4466995d5b7e2ff2def5e" member_type: VOTER }
I20260812 06:18:55.748962   422 leader_election.cc:304] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [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: bbfb0b4609b4466995d5b7e2ff2def5e; no voters: 
I20260812 06:18:55.749245   422 leader_election.cc:290] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:55.749512   425 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:55.749809   425 raft_consensus.cc:697] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [term 1 LEADER]: Becoming Leader. State: Replica: bbfb0b4609b4466995d5b7e2ff2def5e, State: Running, Role: LEADER
I20260812 06:18:55.750249   425 consensus_queue.cc:237] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [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: "bbfb0b4609b4466995d5b7e2ff2def5e" member_type: VOTER }
I20260812 06:18:55.750367   422 sys_catalog.cc:565] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:55.752614   427 sys_catalog.cc:455] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [sys.catalog]: SysCatalogTable state changed. Reason: New leader bbfb0b4609b4466995d5b7e2ff2def5e. Latest consensus state: current_term: 1 leader_uuid: "bbfb0b4609b4466995d5b7e2ff2def5e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbfb0b4609b4466995d5b7e2ff2def5e" member_type: VOTER } }
I20260812 06:18:55.752740   427 sys_catalog.cc:458] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:55.753007   426 sys_catalog.cc:455] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bbfb0b4609b4466995d5b7e2ff2def5e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbfb0b4609b4466995d5b7e2ff2def5e" member_type: VOTER } }
I20260812 06:18:55.753086   426 sys_catalog.cc:458] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:55.753094   439 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:55.753209   348 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:55.755511   439 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:55.760464   439 catalog_manager.cc:1383] Generated new cluster ID: e52d7ad4a5bc47bd9bec2b1c0e701602
I20260812 06:18:55.760562   439 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:55.771600   439 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:55.772754   439 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:55.781888   439 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e: Generated new TSK 0
I20260812 06:18:55.782639   439 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:55.785712   348 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:55.788404   446 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:18:55.788429   449 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:18:55.788638   447 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:18:55.789184   348 server_base.cc:1061] running on GCE node
I20260812 06:18:55.789378   348 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:55.789427   348 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:18:55.789450   348 hybrid_clock.cc:648] HybridClock initialized: now 1786515535789450 us; error 0 us; skew 500 ppm
I20260812 06:18:55.790450   348 webserver.cc:533] Webserver started at http://127.0.87.1:43119/ using document root <none> and password file <none>
I20260812 06:18:55.790625   348 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:55.790686   348 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:55.790755   348 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:55.791215   348 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/instance:
uuid: "f35ba1224dc642a8ae2a642e665a0455"
format_stamp: "Formatted at 2026-08-12 06:18:55 on dist-test-slave-65mx"
I20260812 06:18:55.794430   348 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:55.795662   455 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:18:55.796015   348 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:55.796092   348 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root
uuid: "f35ba1224dc642a8ae2a642e665a0455"
format_stamp: "Formatted at 2026-08-12 06:18:55 on dist-test-slave-65mx"
I20260812 06:18:55.796197   348 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-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:18:55.814145   348 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:55.814978   348 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:55.815521   348 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:55.816525   348 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:55.816620   348 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:55.816702   348 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:55.816751   348 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:55.824680   348 rpc_server.cc:307] RPC server started. Bound to: 127.0.87.1:45229
I20260812 06:18:55.824707   524 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.87.1:45229 every 8 connection(s)
I20260812 06:18:55.836216   525 heartbeater.cc:344] Connected to a master server at 127.0.87.62:42625
I20260812 06:18:55.836503   525 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:55.837073   525 heartbeater.cc:507] Master 127.0.87.62:42625 requested a full tablet report, sending...
I20260812 06:18:55.838619   382 ts_manager.cc:194] Registered new tserver with Master: f35ba1224dc642a8ae2a642e665a0455 (127.0.87.1:45229)
I20260812 06:18:55.838953   348 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013526428s
I20260812 06:18:55.840171   382 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51076
I20260812 06:18:55.848999   382 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51084:
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:18:55.865026   487 tablet_service.cc:1511] Processing CreateTablet for tablet e172389a47c148c5ac8f9a3567576aa1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=5f98b2b647bc427d99e73168b437c673]), partition=
I20260812 06:18:55.865537   487 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e172389a47c148c5ac8f9a3567576aa1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:55.868160   539 tablet_bootstrap.cc:492] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Bootstrap starting.
I20260812 06:18:55.869378   539 tablet_bootstrap.cc:654] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:55.870705   539 tablet_bootstrap.cc:492] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: No bootstrap required, opened a new log
I20260812 06:18:55.870810   539 ts_tablet_manager.cc:1403] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:55.871296   539 raft_consensus.cc:359] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f35ba1224dc642a8ae2a642e665a0455" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 45229 } }
I20260812 06:18:55.871423   539 raft_consensus.cc:385] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:55.871505   539 raft_consensus.cc:740] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f35ba1224dc642a8ae2a642e665a0455, State: Initialized, Role: FOLLOWER
I20260812 06:18:55.871713   539 consensus_queue.cc:260] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [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: "f35ba1224dc642a8ae2a642e665a0455" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 45229 } }
I20260812 06:18:55.871878   539 raft_consensus.cc:399] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:55.871937   539 raft_consensus.cc:493] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:55.871981   539 raft_consensus.cc:3060] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:55.872962   539 raft_consensus.cc:515] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f35ba1224dc642a8ae2a642e665a0455" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 45229 } }
I20260812 06:18:55.873107   539 leader_election.cc:304] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [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: f35ba1224dc642a8ae2a642e665a0455; no voters: 
I20260812 06:18:55.873311   539 leader_election.cc:290] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:55.873512   541 raft_consensus.cc:2804] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:55.873618   539 ts_tablet_manager.cc:1434] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:18:55.873782   541 raft_consensus.cc:697] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [term 1 LEADER]: Becoming Leader. State: Replica: f35ba1224dc642a8ae2a642e665a0455, State: Running, Role: LEADER
I20260812 06:18:55.873898   525 heartbeater.cc:499] Master 127.0.87.62:42625 was elected leader, sending a full tablet report...
I20260812 06:18:55.874029   541 consensus_queue.cc:237] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [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: "f35ba1224dc642a8ae2a642e665a0455" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 45229 } }
I20260812 06:18:55.877167   382 catalog_manager.cc:5719] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 reported cstate change: term changed from 0 to 1, leader changed from <none> to f35ba1224dc642a8ae2a642e665a0455 (127.0.87.1). New cstate: current_term: 1 leader_uuid: "f35ba1224dc642a8ae2a642e665a0455" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f35ba1224dc642a8ae2a642e665a0455" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 45229 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:55.951298   348 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.066s	user 0.027s	sys 0.004s
I20260812 06:18:56.076102   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushMRSOp(e172389a47c148c5ac8f9a3567576aa1): perf score=15.086190
I20260812 06:18:56.250689   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushMRSOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.174s	user 0.116s	sys 0.043s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":227,"delete_count":0,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":861,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39302,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":140,"threads_started":1,"update_count":1500}
I20260812 06:18:56.252177   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling LogGCOp(e172389a47c148c5ac8f9a3567576aa1): free 20290830 bytes of WAL
I20260812 06:18:56.252516   464 log_reader.cc:385] T e172389a47c148c5ac8f9a3567576aa1: removed 2 log segments from log reader
I20260812 06:18:56.252662   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000001 (ops 1-6)
I20260812 06:18:56.252782   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000002 (ops 7-10)
I20260812 06:18:56.258848   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: LogGCOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:56.259630   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:56.278631   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.019s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6578,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.279438   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:56.411068   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.131s	user 0.092s	sys 0.039s 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":584,"lbm_read_time_us":8350,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25797,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":296,"threads_started":5,"update_count":2000}
I20260812 06:18:56.411618   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling UndoDeltaBlockGCOp(e172389a47c148c5ac8f9a3567576aa1): 12308959 bytes on disk
I20260812 06:18:56.412091   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: UndoDeltaBlockGCOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:56.412535   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=10.126437
I20260812 06:18:56.456602   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.044s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20741,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.457062   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:56.468911   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.469413   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:56.595072   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.125s	user 0.100s	sys 0.025s 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":1201,"lbm_read_time_us":10079,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22313,"lbm_writes_lt_1ms":443,"mutex_wait_us":330,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:18:56.595708   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=10.126437
I20260812 06:18:56.636205   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.040s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17719,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.636817   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:56.652997   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.653584   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:56.784169   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.130s	user 0.109s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":9593,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23231,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.784894   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=10.126437
I20260812 06:18:56.837944   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.053s	user 0.023s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17782,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.838521   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:56.850139   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4443,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.850718   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:57.001758   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.151s	user 0.107s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1004,"lbm_read_time_us":11588,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24573,"lbm_writes_lt_1ms":443,"mutex_wait_us":317,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:18:57.002332   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=10.126437
I20260812 06:18:57.058941   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.056s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16457,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.059820   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:57.072155   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4423,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.072980   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:57.201148   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.128s	user 0.096s	sys 0.032s 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":841,"lbm_read_time_us":10959,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23130,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:18:57.201753   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=10.126437
I20260812 06:18:57.244796   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.043s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16293,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.245257   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:57.256198   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4197,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.256721   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:57.384290   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.127s	user 0.086s	sys 0.041s 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":189,"lbm_read_time_us":9418,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25330,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:18:57.384835   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=10.126437
I20260812 06:18:57.434710   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.050s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18593,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:57.435243   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:57.447278   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4267,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.447781   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushMRSOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:57.479061   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushMRSOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.031s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1360,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1916,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:57.479959   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling LogGCOp(e172389a47c148c5ac8f9a3567576aa1): free 108988503 bytes of WAL
I20260812 06:18:57.480237   464 log_reader.cc:385] T e172389a47c148c5ac8f9a3567576aa1: removed 11 log segments from log reader
I20260812 06:18:57.480309   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000003 (ops 11-15)
I20260812 06:18:57.480363   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000004 (ops 16-20)
I20260812 06:18:57.480422   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000005 (ops 21-25)
I20260812 06:18:57.480464   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000006 (ops 26-30)
I20260812 06:18:57.480500   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000007 (ops 31-34)
I20260812 06:18:57.480536   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000008 (ops 35-39)
I20260812 06:18:57.480600   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000009 (ops 40-44)
I20260812 06:18:57.480636   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000010 (ops 45-49)
I20260812 06:18:57.480675   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000011 (ops 50-54)
I20260812 06:18:57.480710   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000012 (ops 55-59)
I20260812 06:18:57.480747   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000013 (ops 60-64)
I20260812 06:18:57.507030   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: LogGCOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.027s	user 0.005s	sys 0.019s Metrics: {}
I20260812 06:18:57.507498   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling UndoDeltaBlockGCOp(e172389a47c148c5ac8f9a3567576aa1): 447 bytes on disk
I20260812 06:18:57.508025   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: UndoDeltaBlockGCOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:18:57.508526   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=3.181125
I20260812 06:18:57.520749   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4416,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:57.521255   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:57.531396   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3661,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:57.531955   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:57.697003   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.165s	user 0.121s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":234,"lbm_read_time_us":10994,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33803,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:18:57.697688   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=14.095187
I20260812 06:18:57.753878   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.056s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24903,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:57.754374   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:57.766212   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.766711   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:57.926349   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.159s	user 0.119s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":275,"lbm_read_time_us":10515,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30584,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:57.927120   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=14.095187
I20260812 06:18:57.980365   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.053s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22045,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.981001   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:58.267326   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.286s	user 0.180s	sys 0.068s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":962,"lbm_read_time_us":9652,"lbm_reads_lt_1ms":463,"lbm_write_time_us":49362,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.269234   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=14.095187
I20260812 06:18:58.404048   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.134s	user 0.063s	sys 0.052s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":54740,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.405192   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:58.441332   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.036s	user 0.014s	sys 0.021s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":14636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.442500   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:58.985767   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.543s	user 0.345s	sys 0.180s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1055,"lbm_read_time_us":38340,"lbm_reads_lt_1ms":572,"lbm_write_time_us":108538,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":541,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27776,"thread_start_us":404,"threads_started":6,"update_count":2500}
I20260812 06:18:58.986454   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=14.095187
I20260812 06:18:59.039496   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.053s	user 0.024s	sys 0.025s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23614,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.040045   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:59.057808   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.018s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6884,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.058338   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:59.210666   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.152s	user 0.117s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1266,"lbm_read_time_us":9595,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29362,"lbm_writes_lt_1ms":543,"mutex_wait_us":344,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:18:59.211277   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=11.118625
I20260812 06:18:59.248219   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.037s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15722,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:59.249010   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:59.268810   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.020s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5879,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.269366   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:59.279331   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3797,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:59.279845   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:59.443571   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.164s	user 0.128s	sys 0.035s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":444,"lbm_read_time_us":12155,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32721,"lbm_writes_lt_1ms":543,"mutex_wait_us":93,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":2500}
I20260812 06:18:59.444375   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=11.118625
I20260812 06:18:59.484912   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.040s	user 0.026s	sys 0.013s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16584,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:59.485826   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:59.502079   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5910,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":450}
I20260812 06:18:59.502650   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushMRSOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:59.554471   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushMRSOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.052s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1681,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2046,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:59.555307   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling LogGCOp(e172389a47c148c5ac8f9a3567576aa1): free 120553382 bytes of WAL
I20260812 06:18:59.555588   464 log_reader.cc:385] T e172389a47c148c5ac8f9a3567576aa1: removed 12 log segments from log reader
I20260812 06:18:59.555660   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000014 (ops 65-69)
I20260812 06:18:59.555701   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000015 (ops 70-74)
I20260812 06:18:59.555732   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000016 (ops 75-78)
I20260812 06:18:59.555765   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000017 (ops 79-83)
I20260812 06:18:59.555801   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000018 (ops 84-88)
I20260812 06:18:59.555835   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000019 (ops 89-93)
I20260812 06:18:59.555857   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000020 (ops 94-98)
I20260812 06:18:59.555879   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000021 (ops 99-103)
I20260812 06:18:59.555902   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000022 (ops 104-108)
I20260812 06:18:59.555934   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000023 (ops 109-112)
I20260812 06:18:59.555967   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000024 (ops 113-117)
I20260812 06:18:59.555998   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000025 (ops 118-122)
I20260812 06:18:59.585392   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: LogGCOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:59.585922   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=6.157687
I20260812 06:18:59.609045   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.023s	user 0.010s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9543,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:59.609519   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling LogGCOp(e172389a47c148c5ac8f9a3567576aa1): free 12017874 bytes of WAL
I20260812 06:18:59.609742   464 log_reader.cc:385] T e172389a47c148c5ac8f9a3567576aa1: removed 1 log segments from log reader
I20260812 06:18:59.609784   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000026 (ops 123-127)
I20260812 06:18:59.612730   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: LogGCOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:59.613077   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling UndoDeltaBlockGCOp(e172389a47c148c5ac8f9a3567576aa1): 484 bytes on disk
I20260812 06:18:59.613521   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: UndoDeltaBlockGCOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:18:59.614003   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:59.635349   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.021s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4741,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.635967   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:18:59.864416   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.228s	user 0.145s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938780,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":741,"lbm_read_time_us":17514,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37301,"lbm_writes_lt_1ms":743,"mutex_wait_us":45,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15744,"thread_start_us":135,"threads_started":1,"update_count":3500}
I20260812 06:18:59.865178   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=18.063937
I20260812 06:18:59.931453   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.066s	user 0.052s	sys 0.011s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":29713,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:59.932240   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:18:59.950800   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.951376   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:19:00.152568   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.201s	user 0.155s	sys 0.044s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1090,"lbm_read_time_us":14946,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35177,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28160,"update_count":3000}
I20260812 06:19:00.153549   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=14.095187
I20260812 06:19:00.214378   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.061s	user 0.045s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26625,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.215127   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:19:00.225791   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4183,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.226444   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:19:00.414456   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.188s	user 0.144s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1022,"lbm_read_time_us":13614,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34327,"lbm_writes_lt_1ms":543,"mutex_wait_us":256,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:00.415020   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=14.095187
I20260812 06:19:00.483453   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.068s	user 0.025s	sys 0.038s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23823,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.484086   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:19:00.495363   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4499,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.495885   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:19:00.686035   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.190s	user 0.130s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":806,"lbm_read_time_us":13999,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32007,"lbm_writes_lt_1ms":543,"mutex_wait_us":292,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:19:00.686723   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=11.118625
I20260812 06:19:00.728675   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.042s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18415,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:00.729288   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:19:00.742758   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.013s	user 0.002s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5124,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:00.743317   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:19:00.910674   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.167s	user 0.118s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":558,"lbm_read_time_us":8576,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26162,"lbm_writes_lt_1ms":443,"mutex_wait_us":193,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:19:00.911383   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=14.095187
I20260812 06:19:00.961958   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.050s	user 0.041s	sys 0.003s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20031,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.962492   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:19:00.973729   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4108,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.974483   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:19:01.130949   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.156s	user 0.116s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":729,"lbm_read_time_us":9780,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31472,"lbm_writes_lt_1ms":543,"mutex_wait_us":322,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:19:01.131543   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=14.095187
I20260812 06:19:01.180907   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.049s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20364,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.181537   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:19:01.194082   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4683,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.194579   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushMRSOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:19:01.229954   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushMRSOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.035s	user 0.028s	sys 0.005s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1656,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1692,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:01.230654   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling LogGCOp(e172389a47c148c5ac8f9a3567576aa1): free 124710558 bytes of WAL
I20260812 06:19:01.230893   464 log_reader.cc:385] T e172389a47c148c5ac8f9a3567576aa1: removed 12 log segments from log reader
I20260812 06:19:01.230957   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000027 (ops 128-132)
I20260812 06:19:01.231014   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000028 (ops 133-137)
I20260812 06:19:01.231071   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000029 (ops 138-142)
I20260812 06:19:01.231114   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000030 (ops 143-147)
I20260812 06:19:01.231153   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000031 (ops 148-152)
I20260812 06:19:01.231191   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000032 (ops 153-157)
I20260812 06:19:01.231231   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000033 (ops 158-162)
I20260812 06:19:01.231271   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000034 (ops 163-167)
I20260812 06:19:01.231308   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000035 (ops 168-172)
I20260812 06:19:01.231346   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000036 (ops 173-177)
I20260812 06:19:01.231385   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000037 (ops 178-182)
I20260812 06:19:01.231426   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000038 (ops 183-187)
I20260812 06:19:01.262926   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: LogGCOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:01.263441   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=3.181125
I20260812 06:19:01.281510   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.018s	user 0.008s	sys 0.009s Metrics: {"bytes_written":4759047,"delete_count":0,"lbm_write_time_us":7460,"lbm_writes_lt_1ms":119,"reinsert_count":0,"update_count":580}
I20260812 06:19:01.282101   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling LogGCOp(e172389a47c148c5ac8f9a3567576aa1): free 12018004 bytes of WAL
I20260812 06:19:01.282337   464 log_reader.cc:385] T e172389a47c148c5ac8f9a3567576aa1: removed 1 log segments from log reader
I20260812 06:19:01.282403   464 log.cc:1079] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515535660812-348-0/minicluster-data/ts-0-root/wals/e172389a47c148c5ac8f9a3567576aa1/wal-000000039 (ops 188-192)
I20260812 06:19:01.284823   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: LogGCOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:01.285169   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling UndoDeltaBlockGCOp(e172389a47c148c5ac8f9a3567576aa1): 493 bytes on disk
I20260812 06:19:01.285575   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: UndoDeltaBlockGCOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.286070   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=2.188937
I20260812 06:19:01.298087   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.012s	user 0.004s	sys 0.006s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":4009,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:19:01.298632   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:19:01.510872   348 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.559s	user 2.021s	sys 0.143s
I20260812 06:19:01.530550   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.232s	user 0.159s	sys 0.065s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938769,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16396,"lbm_reads_lt_1ms":770,"lbm_write_time_us":40209,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3500}
I20260812 06:19:01.531082   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1): perf score=14.095187
I20260812 06:19:01.567433   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: FlushDeltaMemStoresOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.036s	user 0.006s	sys 0.029s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17563,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.567978   526 maintenance_manager.cc:419] P f35ba1224dc642a8ae2a642e665a0455: Scheduling MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1): perf score=1.000000
I20260812 06:19:01.591261   348 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.080s	user 0.003s	sys 0.000s
I20260812 06:19:01.592288   348 tablet_server.cc:179] TabletServer@127.0.87.1:0 shutting down...
I20260812 06:19:01.696519   464 maintenance_manager.cc:643] P f35ba1224dc642a8ae2a642e665a0455: MajorDeltaCompactionOp(e172389a47c148c5ac8f9a3567576aa1) complete. Timing: real 0.128s	user 0.090s	sys 0.035s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":472,"lbm_read_time_us":10004,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24400,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.697396   348 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:01.697887   348 tablet_replica.cc:333] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455: stopping tablet replica
I20260812 06:19:01.698177   348 raft_consensus.cc:2243] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:01.698423   348 raft_consensus.cc:2272] T e172389a47c148c5ac8f9a3567576aa1 P f35ba1224dc642a8ae2a642e665a0455 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:01.714195   348 tablet_server.cc:196] TabletServer@127.0.87.1:0 shutdown complete.
I20260812 06:19:01.739326   348 master.cc:562] Master@127.0.87.62:42625 shutting down...
I20260812 06:19:01.743775   348 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:01.744017   348 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:01.744124   348 tablet_replica.cc:333] T 00000000000000000000000000000000 P bbfb0b4609b4466995d5b7e2ff2def5e: stopping tablet replica
I20260812 06:19:01.756814   348 master.cc:584] Master@127.0.87.62:42625 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6175 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:01.846612   348 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.87.62:45607
I20260812 06:19:01.847038   348 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:01.849644   566 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:01.849677   569 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:01.849689   348 server_base.cc:1061] running on GCE node
W20260812 06:19:01.849699   567 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:01.850054   348 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:01.850095   348 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:01.850117   348 hybrid_clock.cc:648] HybridClock initialized: now 1786515541850118 us; error 0 us; skew 500 ppm
I20260812 06:19:01.851063   348 webserver.cc:533] Webserver started at http://127.0.87.62:40189/ using document root <none> and password file <none>
I20260812 06:19:01.851257   348 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:01.851300   348 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:01.851365   348 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:01.851753   348 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/master-0-root/instance:
uuid: "778c47675f2b425aae45211769e8ca2f"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-65mx"
I20260812 06:19:01.853395   348 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:01.854435   574 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:01.854832   348 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:01.854905   348 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/master-0-root
uuid: "778c47675f2b425aae45211769e8ca2f"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-65mx"
I20260812 06:19:01.855017   348 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:01.874049   348 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:01.874519   348 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:01.879050   348 rpc_server.cc:307] RPC server started. Bound to: 127.0.87.62:45607
I20260812 06:19:01.882884   631 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.87.62:45607 every 8 connection(s)
I20260812 06:19:01.884119   633 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:01.898402   633 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f: Bootstrap starting.
I20260812 06:19:01.899293   633 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:01.900497   633 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f: No bootstrap required, opened a new log
I20260812 06:19:01.901139   633 raft_consensus.cc:359] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "778c47675f2b425aae45211769e8ca2f" member_type: VOTER }
I20260812 06:19:01.901252   633 raft_consensus.cc:385] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:01.901278   633 raft_consensus.cc:740] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 778c47675f2b425aae45211769e8ca2f, State: Initialized, Role: FOLLOWER
I20260812 06:19:01.901456   633 consensus_queue.cc:260] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [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: "778c47675f2b425aae45211769e8ca2f" member_type: VOTER }
I20260812 06:19:01.901572   633 raft_consensus.cc:399] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:01.901603   633 raft_consensus.cc:493] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:01.901638   633 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:01.902490   633 raft_consensus.cc:515] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "778c47675f2b425aae45211769e8ca2f" member_type: VOTER }
I20260812 06:19:01.902629   633 leader_election.cc:304] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [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: 778c47675f2b425aae45211769e8ca2f; no voters: 
I20260812 06:19:01.902825   633 leader_election.cc:290] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:01.903012   636 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:01.903261   636 raft_consensus.cc:697] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [term 1 LEADER]: Becoming Leader. State: Replica: 778c47675f2b425aae45211769e8ca2f, State: Running, Role: LEADER
I20260812 06:19:01.903410   633 sys_catalog.cc:565] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:01.903430   636 consensus_queue.cc:237] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [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: "778c47675f2b425aae45211769e8ca2f" member_type: VOTER }
I20260812 06:19:01.903980   637 sys_catalog.cc:455] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "778c47675f2b425aae45211769e8ca2f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "778c47675f2b425aae45211769e8ca2f" member_type: VOTER } }
I20260812 06:19:01.904033   638 sys_catalog.cc:455] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 778c47675f2b425aae45211769e8ca2f. Latest consensus state: current_term: 1 leader_uuid: "778c47675f2b425aae45211769e8ca2f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "778c47675f2b425aae45211769e8ca2f" member_type: VOTER } }
I20260812 06:19:01.904158   637 sys_catalog.cc:458] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:01.904249   638 sys_catalog.cc:458] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:01.904804   642 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:01.905794   642 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:01.906032   348 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:01.907723   642 catalog_manager.cc:1383] Generated new cluster ID: 88f3992dfcc34ae38ee35ae7867de658
I20260812 06:19:01.907788   642 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:01.915072   642 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:01.915695   642 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:01.924583   642 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f: Generated new TSK 0
I20260812 06:19:01.924815   642 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:01.938838   348 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:01.941037   654 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:01.941082   657 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:01.941111   655 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:01.941282   348 server_base.cc:1061] running on GCE node
I20260812 06:19:01.941483   348 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:01.941524   348 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:01.941542   348 hybrid_clock.cc:648] HybridClock initialized: now 1786515541941542 us; error 0 us; skew 500 ppm
I20260812 06:19:01.942404   348 webserver.cc:533] Webserver started at http://127.0.87.1:39469/ using document root <none> and password file <none>
I20260812 06:19:01.942552   348 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:01.942597   348 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:01.942656   348 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:01.943058   348 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/instance:
uuid: "a0cebed42935453fa9292d439af3989b"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-65mx"
I20260812 06:19:01.944715   348 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:01.945827   663 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:01.946084   348 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:01.946208   348 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root
uuid: "a0cebed42935453fa9292d439af3989b"
format_stamp: "Formatted at 2026-08-12 06:19:01 on dist-test-slave-65mx"
I20260812 06:19:01.946300   348 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:01.958451   348 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:01.958880   348 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:01.959224   348 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:01.959733   348 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:01.959794   348 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:01.959858   348 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:01.959894   348 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:01.964937   348 rpc_server.cc:307] RPC server started. Bound to: 127.0.87.1:44729
I20260812 06:19:01.964962   729 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.87.1:44729 every 8 connection(s)
I20260812 06:19:01.974874   730 heartbeater.cc:344] Connected to a master server at 127.0.87.62:45607
I20260812 06:19:01.975029   730 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:01.975281   730 heartbeater.cc:507] Master 127.0.87.62:45607 requested a full tablet report, sending...
I20260812 06:19:01.976012   591 ts_manager.cc:194] Registered new tserver with Master: a0cebed42935453fa9292d439af3989b (127.0.87.1:44729)
I20260812 06:19:01.976643   348 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011168025s
I20260812 06:19:01.976856   591 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50974
I20260812 06:19:01.984753   591 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50980:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:01.994145   692 tablet_service.cc:1511] Processing CreateTablet for tablet 44a4089ed94f4d84abce4ed0e31f4571 (DEFAULT_TABLE table=heavy-update-compaction-test [id=795a256894bc4b37b0f8f9cc0636c823]), partition=
I20260812 06:19:01.994468   692 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 44a4089ed94f4d84abce4ed0e31f4571. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:01.996598   743 tablet_bootstrap.cc:492] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Bootstrap starting.
I20260812 06:19:01.997491   743 tablet_bootstrap.cc:654] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:01.998641   743 tablet_bootstrap.cc:492] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: No bootstrap required, opened a new log
I20260812 06:19:01.998732   743 ts_tablet_manager.cc:1403] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:01.999102   743 raft_consensus.cc:359] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0cebed42935453fa9292d439af3989b" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 44729 } }
I20260812 06:19:01.999260   743 raft_consensus.cc:385] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:01.999332   743 raft_consensus.cc:740] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a0cebed42935453fa9292d439af3989b, State: Initialized, Role: FOLLOWER
I20260812 06:19:01.999490   743 consensus_queue.cc:260] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [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: "a0cebed42935453fa9292d439af3989b" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 44729 } }
I20260812 06:19:01.999603   743 raft_consensus.cc:399] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:01.999650   743 raft_consensus.cc:493] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:01.999706   743 raft_consensus.cc:3060] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.000485   743 raft_consensus.cc:515] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0cebed42935453fa9292d439af3989b" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 44729 } }
I20260812 06:19:02.000675   743 leader_election.cc:304] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [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: a0cebed42935453fa9292d439af3989b; no voters: 
I20260812 06:19:02.000888   743 leader_election.cc:290] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.001030   745 raft_consensus.cc:2804] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.001246   743 ts_tablet_manager.cc:1434] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:02.001257   730 heartbeater.cc:499] Master 127.0.87.62:45607 was elected leader, sending a full tablet report...
I20260812 06:19:02.001307   745 raft_consensus.cc:697] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [term 1 LEADER]: Becoming Leader. State: Replica: a0cebed42935453fa9292d439af3989b, State: Running, Role: LEADER
I20260812 06:19:02.001514   745 consensus_queue.cc:237] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [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: "a0cebed42935453fa9292d439af3989b" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 44729 } }
I20260812 06:19:02.002889   591 catalog_manager.cc:5719] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b reported cstate change: term changed from 0 to 1, leader changed from <none> to a0cebed42935453fa9292d439af3989b (127.0.87.1). New cstate: current_term: 1 leader_uuid: "a0cebed42935453fa9292d439af3989b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a0cebed42935453fa9292d439af3989b" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 44729 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:02.068871   348 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.016s	sys 0.007s
I20260812 06:19:02.216058   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushMRSOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=19.054940
I20260812 06:19:02.374830   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushMRSOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.158s	user 0.112s	sys 0.044s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":936,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43500,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:02.375484   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling LogGCOp(44a4089ed94f4d84abce4ed0e31f4571): free 20743880 bytes of WAL
I20260812 06:19:02.375779   668 log_reader.cc:385] T 44a4089ed94f4d84abce4ed0e31f4571: removed 2 log segments from log reader
I20260812 06:19:02.375839   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000001 (ops 1-6)
I20260812 06:19:02.375880   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000002 (ops 7-11)
I20260812 06:19:02.380357   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: LogGCOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:02.380774   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling UndoDeltaBlockGCOp(44a4089ed94f4d84abce4ed0e31f4571): 16411398 bytes on disk
I20260812 06:19:02.381229   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: UndoDeltaBlockGCOp(44a4089ed94f4d84abce4ed0e31f4571) 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:19:02.381635   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:02.399866   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.400445   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:02.548916   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.148s	user 0.107s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1002,"lbm_read_time_us":9993,"lbm_reads_lt_1ms":460,"lbm_write_time_us":24823,"lbm_writes_lt_1ms":443,"mutex_wait_us":81,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"thread_start_us":360,"threads_started":5,"update_count":2000}
I20260812 06:19:02.549572   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=14.095187
I20260812 06:19:02.596462   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.047s	user 0.019s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20836,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.597137   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:02.613109   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5851,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.613780   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:02.787037   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.173s	user 0.103s	sys 0.063s 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":1026,"lbm_read_time_us":12299,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32034,"lbm_writes_lt_1ms":543,"mutex_wait_us":294,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2500}
I20260812 06:19:02.787703   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=12.110812
I20260812 06:19:02.826988   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.039s	user 0.024s	sys 0.013s Metrics: {"bytes_written":13538209,"delete_count":0,"lbm_write_time_us":16592,"lbm_writes_lt_1ms":333,"reinsert_count":0,"update_count":1650}
I20260812 06:19:02.827502   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.196750
I20260812 06:19:02.849519   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.022s	user 0.004s	sys 0.009s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":4748,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:19:02.850153   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:02.865162   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.015s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.865765   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:03.056591   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.191s	user 0.131s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774773,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":340,"lbm_read_time_us":14058,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30559,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2500}
I20260812 06:19:03.057322   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=14.095187
I20260812 06:19:03.117004   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.060s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20548,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.117631   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:03.128348   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.128895   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:03.310338   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.181s	user 0.106s	sys 0.070s 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":890,"lbm_read_time_us":14352,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29060,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:19:03.310847   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=14.095187
I20260812 06:19:03.371958   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.061s	user 0.024s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21502,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.372648   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:03.383658   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4388,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.384150   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:03.567581   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.183s	user 0.133s	sys 0.047s 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":669,"lbm_read_time_us":13570,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29850,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:19:03.569378   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=14.095187
I20260812 06:19:03.635341   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.066s	user 0.025s	sys 0.036s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23545,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.635938   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:03.646865   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4284,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.647396   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushMRSOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:03.680989   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushMRSOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.033s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":1386,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1466,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":1920}
I20260812 06:19:03.681826   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:03.856611   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.175s	user 0.106s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1220,"lbm_read_time_us":11050,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29940,"lbm_writes_lt_1ms":543,"mutex_wait_us":323,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:19:03.857290   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling LogGCOp(44a4089ed94f4d84abce4ed0e31f4571): free 120553333 bytes of WAL
I20260812 06:19:03.857686   668 log_reader.cc:385] T 44a4089ed94f4d84abce4ed0e31f4571: removed 12 log segments from log reader
I20260812 06:19:03.857755   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000003 (ops 12-16)
I20260812 06:19:03.857806   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000004 (ops 17-20)
I20260812 06:19:03.857897   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000005 (ops 21-25)
I20260812 06:19:03.857947   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000006 (ops 26-30)
I20260812 06:19:03.857985   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000007 (ops 31-34)
I20260812 06:19:03.858042   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000008 (ops 35-39)
I20260812 06:19:03.858083   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000009 (ops 40-44)
I20260812 06:19:03.858126   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000010 (ops 45-49)
I20260812 06:19:03.858166   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000011 (ops 50-54)
I20260812 06:19:03.858208   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000012 (ops 55-59)
I20260812 06:19:03.858250   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000013 (ops 60-64)
I20260812 06:19:03.858294   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000014 (ops 65-69)
I20260812 06:19:03.886464   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: LogGCOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:03.887107   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling UndoDeltaBlockGCOp(44a4089ed94f4d84abce4ed0e31f4571): 462 bytes on disk
I20260812 06:19:03.887578   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: UndoDeltaBlockGCOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.888188   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=15.087375
I20260812 06:19:03.946635   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.058s	user 0.031s	sys 0.025s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":20871,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:03.947158   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=3.181125
I20260812 06:19:03.962242   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":5005190,"delete_count":0,"lbm_write_time_us":5986,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:19:03.962862   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.196750
I20260812 06:19:03.971868   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.009s	user 0.000s	sys 0.007s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":3256,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:19:03.972395   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:04.186802   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.214s	user 0.120s	sys 0.093s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877189,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":515,"lbm_read_time_us":16900,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36313,"lbm_writes_lt_1ms":643,"mutex_wait_us":259,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":3000}
I20260812 06:19:04.187577   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=15.087375
I20260812 06:19:04.251995   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.064s	user 0.040s	sys 0.018s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":25763,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:04.252770   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:04.271776   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.019s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4100,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.272243   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:04.283051   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.011s	user 0.009s	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:19:04.283496   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:04.494073   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.210s	user 0.132s	sys 0.077s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":410,"lbm_read_time_us":13824,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31681,"lbm_writes_lt_1ms":643,"mutex_wait_us":107,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":3000}
I20260812 06:19:04.495339   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=16.079562
I20260812 06:19:04.561321   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.066s	user 0.047s	sys 0.013s Metrics: {"bytes_written":17681651,"delete_count":0,"lbm_write_time_us":27506,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2155}
I20260812 06:19:04.561843   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:04.577100   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":5119,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:19:04.577600   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:04.587558   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3817,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.588037   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:04.800745   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.213s	user 0.162s	sys 0.049s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877190,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":706,"lbm_read_time_us":13763,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37594,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":25984,"update_count":3000}
I20260812 06:19:04.801445   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=14.095187
I20260812 06:19:04.862982   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.061s	user 0.028s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25292,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.863551   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:04.874682   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4052,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.875598   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:05.055171   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.179s	user 0.127s	sys 0.050s 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":295,"lbm_read_time_us":14434,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27761,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":2500}
I20260812 06:19:05.055896   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=14.095187
I20260812 06:19:05.123353   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.067s	user 0.036s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22002,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.124089   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:05.135985   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.136523   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushMRSOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:05.181941   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushMRSOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.045s	user 0.030s	sys 0.005s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":300,"dirs.run_wall_time_us":1710,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1573,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:05.182714   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling LogGCOp(44a4089ed94f4d84abce4ed0e31f4571): free 115943248 bytes of WAL
I20260812 06:19:05.182946   668 log_reader.cc:385] T 44a4089ed94f4d84abce4ed0e31f4571: removed 11 log segments from log reader
I20260812 06:19:05.183017   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000015 (ops 70-74)
I20260812 06:19:05.183076   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000016 (ops 75-79)
I20260812 06:19:05.183135   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000017 (ops 80-84)
I20260812 06:19:05.183176   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000018 (ops 85-89)
I20260812 06:19:05.183213   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000019 (ops 90-94)
I20260812 06:19:05.183254   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000020 (ops 95-99)
I20260812 06:19:05.183292   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000021 (ops 100-104)
I20260812 06:19:05.183331   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000022 (ops 105-109)
I20260812 06:19:05.183368   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000023 (ops 110-114)
I20260812 06:19:05.183408   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000024 (ops 115-119)
I20260812 06:19:05.183445   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000025 (ops 120-124)
I20260812 06:19:05.210348   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: LogGCOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:05.210925   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=3.181125
I20260812 06:19:05.228228   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.017s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5006,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:05.228796   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:05.242755   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5263,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:05.243386   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling UndoDeltaBlockGCOp(44a4089ed94f4d84abce4ed0e31f4571): 447 bytes on disk
I20260812 06:19:05.244024   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: UndoDeltaBlockGCOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":90,"lbm_reads_lt_1ms":4}
I20260812 06:19:05.244886   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:05.482290   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.237s	user 0.159s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":154,"lbm_read_time_us":18082,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39613,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9856,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:19:05.483049   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=15.087375
I20260812 06:19:05.547760   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.064s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":24060,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:05.548343   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=6.157687
I20260812 06:19:05.577855   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.029s	user 0.020s	sys 0.007s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":11993,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:05.578419   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:05.752012   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.173s	user 0.129s	sys 0.044s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":549,"lbm_read_time_us":12903,"lbm_reads_lt_1ms":668,"lbm_write_time_us":34510,"lbm_writes_lt_1ms":643,"mutex_wait_us":302,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":3000}
I20260812 06:19:05.752880   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=14.095187
I20260812 06:19:05.800765   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.048s	user 0.026s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20991,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.801383   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:05.819886   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.018s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7408,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.820387   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:05.986769   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.166s	user 0.114s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":445,"lbm_read_time_us":11475,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28802,"lbm_writes_lt_1ms":543,"mutex_wait_us":88,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2500}
I20260812 06:19:05.987555   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=14.095187
I20260812 06:19:06.055088   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.067s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24683,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.055650   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:06.066658   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4267,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.067253   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:06.248829   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.181s	user 0.114s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":353,"lbm_read_time_us":13736,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29562,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2500}
I20260812 06:19:06.249478   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=14.095187
I20260812 06:19:06.309870   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.060s	user 0.034s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24149,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.310513   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:06.328285   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.018s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.329059   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:06.514957   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.186s	user 0.114s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":14165,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31004,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:19:06.515671   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=14.095187
I20260812 06:19:06.579919   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.064s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20533,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.580614   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:06.591620   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4432,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.592098   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushMRSOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:06.636940   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushMRSOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.045s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1430,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1442,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:06.637663   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling LogGCOp(44a4089ed94f4d84abce4ed0e31f4571): free 112692590 bytes of WAL
I20260812 06:19:06.637899   668 log_reader.cc:385] T 44a4089ed94f4d84abce4ed0e31f4571: removed 11 log segments from log reader
I20260812 06:19:06.637944   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000026 (ops 125-129)
I20260812 06:19:06.637975   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000027 (ops 130-134)
I20260812 06:19:06.638039   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000028 (ops 135-139)
I20260812 06:19:06.638074   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000029 (ops 140-144)
I20260812 06:19:06.638118   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000030 (ops 145-149)
I20260812 06:19:06.638149   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000031 (ops 150-154)
I20260812 06:19:06.638190   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000032 (ops 155-159)
I20260812 06:19:06.638230   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000033 (ops 160-164)
I20260812 06:19:06.638273   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000034 (ops 165-169)
I20260812 06:19:06.638312   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000035 (ops 170-174)
I20260812 06:19:06.638351   668 log.cc:1079] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: Deleting log segment in path: /tmp/dist-test-taskBQQzj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515535660812-348-0/minicluster-data/ts-0-root/wals/44a4089ed94f4d84abce4ed0e31f4571/wal-000000036 (ops 175-179)
I20260812 06:19:06.662570   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: LogGCOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.025s	user 0.001s	sys 0.022s Metrics: {}
I20260812 06:19:06.663024   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling UndoDeltaBlockGCOp(44a4089ed94f4d84abce4ed0e31f4571): 446 bytes on disk
I20260812 06:19:06.663493   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: UndoDeltaBlockGCOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:19:06.664041   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:06.687781   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.024s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6723,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.688295   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:06.698943   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.699436   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:06.954722   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.255s	user 0.191s	sys 0.051s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":198,"lbm_read_time_us":15557,"lbm_reads_lt_1ms":774,"lbm_write_time_us":46850,"lbm_writes_lt_1ms":743,"mutex_wait_us":21,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13056,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:19:06.955454   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=18.063937
I20260812 06:19:07.016474   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.061s	user 0.028s	sys 0.029s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26727,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:07.017087   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=2.188937
I20260812 06:19:07.028983   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4572,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.029493   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=1.000000
I20260812 06:19:07.151437   348 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.082s	user 1.914s	sys 0.153s
I20260812 06:19:07.217633   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: MajorDeltaCompactionOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.188s	user 0.136s	sys 0.052s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":285,"lbm_read_time_us":12643,"lbm_reads_lt_1ms":668,"lbm_write_time_us":36163,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":3000}
I20260812 06:19:07.218278   731 maintenance_manager.cc:419] P a0cebed42935453fa9292d439af3989b: Scheduling FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571): perf score=10.126437
I20260812 06:19:07.228803   348 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.077s	user 0.003s	sys 0.000s
I20260812 06:19:07.229338   348 tablet_server.cc:179] TabletServer@127.0.87.1:0 shutting down...
I20260812 06:19:07.260308   668 maintenance_manager.cc:643] P a0cebed42935453fa9292d439af3989b: FlushDeltaMemStoresOp(44a4089ed94f4d84abce4ed0e31f4571) complete. Timing: real 0.042s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":21715,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:07.261132   348 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:07.261381   348 tablet_replica.cc:333] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b: stopping tablet replica
I20260812 06:19:07.261693   348 raft_consensus.cc:2243] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.261906   348 raft_consensus.cc:2272] T 44a4089ed94f4d84abce4ed0e31f4571 P a0cebed42935453fa9292d439af3989b [term 1 FOLLOWER]: Raft consensus is shut down!
W20260812 06:19:08.238921   724 debug-util.cc:398] Leaking SignalData structure 0x557c5271dea0 after lost signal to thread 693
W20260812 06:19:08.239108   724 debug-util.cc:398] Leaking SignalData structure 0x557c5271d1a0 after lost signal to thread 694
W20260812 06:19:08.265123   348 thread.cc:527] Waited for 1000ms trying to join with diag-logger (tid 724)
I20260812 06:19:08.576402   348 tablet_server.cc:196] TabletServer@127.0.87.1:0 shutdown complete.
I20260812 06:19:08.579258   348 master.cc:562] Master@127.0.87.62:45607 shutting down...
I20260812 06:19:08.583209   348 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:08.583389   348 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:08.583456   348 tablet_replica.cc:333] T 00000000000000000000000000000000 P 778c47675f2b425aae45211769e8ca2f: stopping tablet replica
I20260812 06:19:08.596184   348 master.cc:584] Master@127.0.87.62:45607 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6847 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (13023 ms total)

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