[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:20:13.608256   348 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.87.62:43295
I20260812 06:20:13.609289   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:20:13.609902   348 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:13.616065   360 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:13.616144   357 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:13.616230   348 server_base.cc:1061] running on GCE node
W20260812 06:20:13.616412   358 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:13.616945   348 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:13.617049   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:20:13.617094   348 hybrid_clock.cc:648] HybridClock initialized: now 1786515613617092 us; error 0 us; skew 500 ppm
I20260812 06:20:13.618871   348 webserver.cc:533] Webserver started at http://127.0.87.62:38037/ using document root <none> and password file <none>
I20260812 06:20:13.619400   348 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:13.619458   348 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:13.619673   348 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:13.621271   348 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/master-0-root/instance:
uuid: "1664eccb7b0b40248f82e723f9f003af"
format_stamp: "Formatted at 2026-08-12 06:20:13 on dist-test-slave-vpvm"
I20260812 06:20:13.624788   348 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:20:13.626928   367 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:13.627909   348 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:13.628038   348 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/master-0-root
uuid: "1664eccb7b0b40248f82e723f9f003af"
format_stamp: "Formatted at 2026-08-12 06:20:13 on dist-test-slave-vpvm"
I20260812 06:20:13.628129   348 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-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:20:13.645059   348 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:13.645684   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:20:13.645841   348 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:13.653110   348 rpc_server.cc:307] RPC server started. Bound to: 127.0.87.62:43295
I20260812 06:20:13.653228   439 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.87.62:43295 every 8 connection(s)
I20260812 06:20:13.655467   441 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:13.661016   441 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af: Bootstrap starting.
I20260812 06:20:13.663450   441 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:13.664359   441 log.cc:826] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:13.666113   441 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af: No bootstrap required, opened a new log
I20260812 06:20:13.668805   441 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1664eccb7b0b40248f82e723f9f003af" member_type: VOTER }
I20260812 06:20:13.668975   441 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:13.669047   441 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1664eccb7b0b40248f82e723f9f003af, State: Initialized, Role: FOLLOWER
I20260812 06:20:13.669690   441 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [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: "1664eccb7b0b40248f82e723f9f003af" member_type: VOTER }
I20260812 06:20:13.669850   441 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:13.669914   441 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:13.670054   441 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:13.670795   441 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1664eccb7b0b40248f82e723f9f003af" member_type: VOTER }
I20260812 06:20:13.671203   441 leader_election.cc:304] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [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: 1664eccb7b0b40248f82e723f9f003af; no voters: 
I20260812 06:20:13.671512   441 leader_election.cc:290] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:13.671656   445 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:13.671868   445 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [term 1 LEADER]: Becoming Leader. State: Replica: 1664eccb7b0b40248f82e723f9f003af, State: Running, Role: LEADER
I20260812 06:20:13.672235   445 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [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: "1664eccb7b0b40248f82e723f9f003af" member_type: VOTER }
I20260812 06:20:13.672410   441 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:13.674130   446 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1664eccb7b0b40248f82e723f9f003af" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1664eccb7b0b40248f82e723f9f003af" member_type: VOTER } }
I20260812 06:20:13.674126   447 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1664eccb7b0b40248f82e723f9f003af. Latest consensus state: current_term: 1 leader_uuid: "1664eccb7b0b40248f82e723f9f003af" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1664eccb7b0b40248f82e723f9f003af" member_type: VOTER } }
I20260812 06:20:13.674266   446 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:13.674266   447 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:13.674590   348 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:20:13.676447   468 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:20:13.676512   468 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:20:13.676591   466 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:13.677407   466 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:13.682080   466 catalog_manager.cc:1383] Generated new cluster ID: 71d5c7b955ea406d89ad7efd65eb996f
I20260812 06:20:13.682140   466 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:13.694728   466 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:13.695938   466 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:13.704867   466 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af: Generated new TSK 0
I20260812 06:20:13.705616   466 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:13.707126   348 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:13.710006   476 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:13.710057   475 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:13.710062   478 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:13.710179   348 server_base.cc:1061] running on GCE node
I20260812 06:20:13.710536   348 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:13.710584   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:20:13.710608   348 hybrid_clock.cc:648] HybridClock initialized: now 1786515613710608 us; error 0 us; skew 500 ppm
I20260812 06:20:13.711571   348 webserver.cc:533] Webserver started at http://127.0.87.1:34039/ using document root <none> and password file <none>
I20260812 06:20:13.711746   348 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:13.711803   348 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:13.711891   348 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:13.712287   348 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/instance:
uuid: "465dbf129b61424ea2d5e1532db350e7"
format_stamp: "Formatted at 2026-08-12 06:20:13 on dist-test-slave-vpvm"
I20260812 06:20:13.713891   348 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:13.714975   491 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:13.715214   348 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:13.715294   348 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root
uuid: "465dbf129b61424ea2d5e1532db350e7"
format_stamp: "Formatted at 2026-08-12 06:20:13 on dist-test-slave-vpvm"
I20260812 06:20:13.715371   348 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-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:20:13.728226   348 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:13.728698   348 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:13.729198   348 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:13.730166   348 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:13.730225   348 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:13.730284   348 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:13.730321   348 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:13.737202   348 rpc_server.cc:307] RPC server started. Bound to: 127.0.87.1:46537
I20260812 06:20:13.737258   585 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.87.1:46537 every 8 connection(s)
I20260812 06:20:13.751533   587 heartbeater.cc:344] Connected to a master server at 127.0.87.62:43295
I20260812 06:20:13.751781   587 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:13.752230   587 heartbeater.cc:507] Master 127.0.87.62:43295 requested a full tablet report, sending...
I20260812 06:20:13.753618   389 ts_manager.cc:194] Registered new tserver with Master: 465dbf129b61424ea2d5e1532db350e7 (127.0.87.1:46537)
I20260812 06:20:13.753712   348 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015830981s
I20260812 06:20:13.754915   389 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59892
I20260812 06:20:13.763458   389 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59896:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:13.777741   533 tablet_service.cc:1511] Processing CreateTablet for tablet 0d49aebb3d1948368d98e8bc89b30a72 (DEFAULT_TABLE table=heavy-update-compaction-test [id=35d6d8fded31453094f858297ff9e35e]), partition=
I20260812 06:20:13.778234   533 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0d49aebb3d1948368d98e8bc89b30a72. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:13.780299   600 tablet_bootstrap.cc:492] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Bootstrap starting.
I20260812 06:20:13.781354   600 tablet_bootstrap.cc:654] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:13.782572   600 tablet_bootstrap.cc:492] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: No bootstrap required, opened a new log
I20260812 06:20:13.782670   600 ts_tablet_manager.cc:1403] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:13.783157   600 raft_consensus.cc:359] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "465dbf129b61424ea2d5e1532db350e7" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 46537 } }
I20260812 06:20:13.783269   600 raft_consensus.cc:385] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:13.783305   600 raft_consensus.cc:740] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 465dbf129b61424ea2d5e1532db350e7, State: Initialized, Role: FOLLOWER
I20260812 06:20:13.783433   600 consensus_queue.cc:260] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [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: "465dbf129b61424ea2d5e1532db350e7" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 46537 } }
I20260812 06:20:13.783540   600 raft_consensus.cc:399] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:13.783579   600 raft_consensus.cc:493] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:13.783624   600 raft_consensus.cc:3060] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:13.784526   600 raft_consensus.cc:515] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "465dbf129b61424ea2d5e1532db350e7" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 46537 } }
I20260812 06:20:13.784670   600 leader_election.cc:304] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [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: 465dbf129b61424ea2d5e1532db350e7; no voters: 
I20260812 06:20:13.784868   600 leader_election.cc:290] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:13.785118   604 raft_consensus.cc:2804] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:13.785189   600 ts_tablet_manager.cc:1434] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:13.785307   604 raft_consensus.cc:697] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [term 1 LEADER]: Becoming Leader. State: Replica: 465dbf129b61424ea2d5e1532db350e7, State: Running, Role: LEADER
I20260812 06:20:13.785501   604 consensus_queue.cc:237] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [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: "465dbf129b61424ea2d5e1532db350e7" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 46537 } }
I20260812 06:20:13.785597   587 heartbeater.cc:499] Master 127.0.87.62:43295 was elected leader, sending a full tablet report...
I20260812 06:20:13.788057   389 catalog_manager.cc:5719] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 465dbf129b61424ea2d5e1532db350e7 (127.0.87.1). New cstate: current_term: 1 leader_uuid: "465dbf129b61424ea2d5e1532db350e7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "465dbf129b61424ea2d5e1532db350e7" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 46537 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:13.854529   348 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.019s	sys 0.007s
I20260812 06:20:13.988351   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushMRSOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=19.054940
I20260812 06:20:14.183615   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushMRSOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.195s	user 0.160s	sys 0.032s Metrics: {"bytes_written":14071528,"cfile_init":1,"compiler_manager_pool.queue_time_us":219,"delete_count":0,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":852,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":49528,"lbm_writes_lt_1ms":800,"mutex_wait_us":894,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":272128,"thread_start_us":108,"threads_started":1,"update_count":1715}
I20260812 06:20:14.184716   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling LogGCOp(0d49aebb3d1948368d98e8bc89b30a72): free 20743880 bytes of WAL
I20260812 06:20:14.185036   500 log_reader.cc:385] T 0d49aebb3d1948368d98e8bc89b30a72: removed 2 log segments from log reader
I20260812 06:20:14.185096   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000001 (ops 1-6)
I20260812 06:20:14.185148   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000002 (ops 7-11)
I20260812 06:20:14.188612   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: LogGCOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:14.189034   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.196750
I20260812 06:20:14.207785   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.019s	user 0.006s	sys 0.006s Metrics: {"bytes_written":2748834,"delete_count":0,"lbm_write_time_us":2385,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:20:14.208282   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling UndoDeltaBlockGCOp(0d49aebb3d1948368d98e8bc89b30a72): 16411392 bytes on disk
I20260812 06:20:14.208942   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: UndoDeltaBlockGCOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:20:14.209401   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:14.223266   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5138,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:14.223824   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:14.382335   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.158s	user 0.142s	sys 0.016s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774767,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":813,"lbm_read_time_us":12035,"lbm_reads_lt_1ms":569,"lbm_write_time_us":25769,"lbm_writes_lt_1ms":543,"mutex_wait_us":142,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":332,"threads_started":5,"update_count":2500}
I20260812 06:20:14.382929   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=10.126437
I20260812 06:20:14.423705   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.041s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12588,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:14.424219   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:14.435032   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3992,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.435786   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:14.559306   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.123s	user 0.102s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":146,"lbm_read_time_us":9097,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22563,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":75904,"update_count":2000}
I20260812 06:20:14.559834   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=10.126437
I20260812 06:20:14.607211   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.047s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15138,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:14.607795   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:14.618866   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3955,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.619453   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:14.739560   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.120s	user 0.090s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":992,"lbm_read_time_us":8672,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20951,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28928,"update_count":2000}
I20260812 06:20:14.740090   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=10.126437
I20260812 06:20:14.777899   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.038s	user 0.011s	sys 0.017s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":13264,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:14.778415   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:14.788492   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3714,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.789078   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:14.908878   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.120s	user 0.100s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":8430,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21831,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:20:14.909379   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=10.126437
I20260812 06:20:14.954721   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.045s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13025,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:14.955448   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:14.965878   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3954,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.966434   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:15.105566   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.139s	user 0.102s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":130,"lbm_read_time_us":10207,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21972,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:20:15.106277   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=10.126437
I20260812 06:20:15.153512   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.047s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14923,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:15.154029   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:15.164640   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3773,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.165309   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:15.285351   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.120s	user 0.094s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":8406,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21933,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:15.285832   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=10.126437
I20260812 06:20:15.325488   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.039s	user 0.014s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12673,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:15.326047   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:15.341331   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5797,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.341751   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushMRSOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:15.374212   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushMRSOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.032s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1194,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1284,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:15.375038   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling LogGCOp(0d49aebb3d1948368d98e8bc89b30a72): free 120553379 bytes of WAL
I20260812 06:20:15.375257   500 log_reader.cc:385] T 0d49aebb3d1948368d98e8bc89b30a72: removed 12 log segments from log reader
I20260812 06:20:15.375303   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000003 (ops 12-16)
I20260812 06:20:15.375331   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000004 (ops 17-21)
I20260812 06:20:15.375361   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000005 (ops 22-26)
I20260812 06:20:15.375394   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000006 (ops 27-31)
I20260812 06:20:15.375416   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000007 (ops 32-36)
I20260812 06:20:15.375447   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000008 (ops 37-40)
I20260812 06:20:15.375478   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000009 (ops 41-45)
I20260812 06:20:15.375509   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000010 (ops 46-50)
I20260812 06:20:15.375540   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000011 (ops 51-55)
I20260812 06:20:15.375569   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000012 (ops 56-60)
I20260812 06:20:15.375602   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000013 (ops 61-64)
I20260812 06:20:15.375636   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000014 (ops 65-69)
I20260812 06:20:15.394920   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: LogGCOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.020s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:20:15.395349   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=3.181125
I20260812 06:20:15.407904   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":3846,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:15.408332   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:15.421840   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4783,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:15.422384   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling UndoDeltaBlockGCOp(0d49aebb3d1948368d98e8bc89b30a72): 462 bytes on disk
I20260812 06:20:15.422935   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: UndoDeltaBlockGCOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:20:15.423460   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:15.594244   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.171s	user 0.122s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3516,"lbm_read_time_us":10660,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33340,"lbm_writes_lt_1ms":643,"mutex_wait_us":47,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":107,"threads_started":1,"update_count":3000}
I20260812 06:20:15.594946   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=14.095187
I20260812 06:20:15.640880   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.046s	user 0.033s	sys 0.005s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17466,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:15.641440   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:15.656497   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5422,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.657014   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:15.808373   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.151s	user 0.125s	sys 0.012s 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":618,"lbm_read_time_us":9694,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26020,"lbm_writes_lt_1ms":543,"mutex_wait_us":269,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:15.808907   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=14.095187
I20260812 06:20:15.861620   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.053s	user 0.031s	sys 0.007s Metrics: {"bytes_written":16409913,"delete_count":0,"lbm_write_time_us":18277,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:15.862221   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:15.872531   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3729,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.873845   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:16.047305   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.173s	user 0.124s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774699,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":12464,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26019,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:20:16.047856   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=14.095187
I20260812 06:20:16.108727   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.061s	user 0.011s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23893,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:20:16.109304   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:16.125281   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6026,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.126295   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:16.299890   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.173s	user 0.131s	sys 0.040s 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":831,"lbm_read_time_us":10108,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31513,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:20:16.300443   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=14.095187
I20260812 06:20:16.353343   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.053s	user 0.024s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16512,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:16.353936   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:16.369773   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6057,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.370479   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:16.531574   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.161s	user 0.113s	sys 0.041s 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":800,"dirs.run_cpu_time_us":2595,"dirs.run_wall_time_us":14821,"lbm_read_time_us":12310,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24386,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:20:16.532222   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=11.118625
I20260812 06:20:16.574959   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.043s	user 0.033s	sys 0.008s Metrics: {"bytes_written":13168993,"delete_count":0,"lbm_write_time_us":17839,"lbm_writes_lt_1ms":324,"reinsert_count":0,"update_count":1605}
I20260812 06:20:16.575524   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:16.589895   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":4914,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:20:16.590562   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:16.734360   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.144s	user 0.114s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672251,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":362,"lbm_read_time_us":9987,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23748,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:20:16.734992   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=10.126437
I20260812 06:20:16.763007   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.028s	user 0.010s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12140,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:16.763549   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:16.776006   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4480,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:16.776623   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushMRSOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:16.806321   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushMRSOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1402,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1685,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:16.807174   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling LogGCOp(0d49aebb3d1948368d98e8bc89b30a72): free 124257256 bytes of WAL
I20260812 06:20:16.807411   500 log_reader.cc:385] T 0d49aebb3d1948368d98e8bc89b30a72: removed 12 log segments from log reader
I20260812 06:20:16.807472   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000015 (ops 70-74)
I20260812 06:20:16.807523   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000016 (ops 75-79)
I20260812 06:20:16.807554   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000017 (ops 80-84)
I20260812 06:20:16.807577   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000018 (ops 85-89)
I20260812 06:20:16.807605   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000019 (ops 90-94)
I20260812 06:20:16.807637   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000020 (ops 95-98)
I20260812 06:20:16.807668   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000021 (ops 99-103)
I20260812 06:20:16.807696   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000022 (ops 104-108)
I20260812 06:20:16.807724   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000023 (ops 109-113)
I20260812 06:20:16.807751   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000024 (ops 114-118)
I20260812 06:20:16.807782   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000025 (ops 119-123)
I20260812 06:20:16.807814   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000026 (ops 124-128)
I20260812 06:20:16.830614   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: LogGCOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.023s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:20:16.830964   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling UndoDeltaBlockGCOp(0d49aebb3d1948368d98e8bc89b30a72): 472 bytes on disk
I20260812 06:20:16.831379   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: UndoDeltaBlockGCOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:20:16.831892   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=3.181125
I20260812 06:20:16.844358   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:16.844741   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:16.853796   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3381,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:16.854233   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:17.036924   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.183s	user 0.130s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":245,"lbm_read_time_us":10778,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30321,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:20:17.037496   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=14.095187
I20260812 06:20:17.087996   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.050s	user 0.043s	sys 0.005s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22517,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.088570   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:17.101022   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4808,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.101511   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:17.279496   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.178s	user 0.116s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":543,"lbm_read_time_us":10901,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25625,"lbm_writes_lt_1ms":543,"mutex_wait_us":270,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:17.280114   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=14.095187
I20260812 06:20:17.330353   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.050s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20562,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:17.330874   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:17.346428   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.015s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5784,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.347018   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:17.495900   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.149s	user 0.105s	sys 0.037s 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":210,"lbm_read_time_us":9807,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28613,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:17.496601   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=11.118625
I20260812 06:20:17.532354   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.036s	user 0.028s	sys 0.005s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14927,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:17.532932   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:17.559234   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.026s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5009,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":450}
I20260812 06:20:17.559800   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:17.570312   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.570789   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:17.706712   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.136s	user 0.119s	sys 0.015s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":186,"lbm_read_time_us":11144,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25005,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:20:17.707345   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=11.118625
I20260812 06:20:17.742231   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.035s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12802,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:17.742791   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:17.758813   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.016s	user 0.002s	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:20:17.759342   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:17.772001   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4682,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:17.772513   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:17.911234   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.139s	user 0.107s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":125,"lbm_read_time_us":9398,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27382,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:17.911880   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=10.126437
I20260812 06:20:17.950423   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.038s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15071,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:17.950959   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:17.967720   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.017s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4849,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:17.968314   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:18.084445   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.116s	user 0.091s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":678,"lbm_read_time_us":6772,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22185,"lbm_writes_lt_1ms":443,"mutex_wait_us":242,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.085144   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=10.126437
I20260812 06:20:18.126986   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.042s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14335,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:18.127588   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:18.142804   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5186,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.143333   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushMRSOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:18.176623   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushMRSOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":125,"dirs.run_wall_time_us":1082,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1939,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:18.177356   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling LogGCOp(0d49aebb3d1948368d98e8bc89b30a72): free 120553636 bytes of WAL
I20260812 06:20:18.177601   500 log_reader.cc:385] T 0d49aebb3d1948368d98e8bc89b30a72: removed 12 log segments from log reader
I20260812 06:20:18.177649   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000027 (ops 129-133)
I20260812 06:20:18.177680   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000028 (ops 134-138)
I20260812 06:20:18.177712   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000029 (ops 139-143)
I20260812 06:20:18.177744   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000030 (ops 144-148)
I20260812 06:20:18.177775   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000031 (ops 149-152)
I20260812 06:20:18.177805   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000032 (ops 153-157)
I20260812 06:20:18.177836   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000033 (ops 158-162)
I20260812 06:20:18.177867   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000034 (ops 163-167)
I20260812 06:20:18.177899   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000035 (ops 168-172)
I20260812 06:20:18.177930   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000036 (ops 173-177)
I20260812 06:20:18.177994   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000037 (ops 178-182)
I20260812 06:20:18.178033   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000038 (ops 183-186)
I20260812 06:20:18.200501   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: LogGCOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.023s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:20:18.200980   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=3.181125
I20260812 06:20:18.223770   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.023s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6620,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:18.224206   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling LogGCOp(0d49aebb3d1948368d98e8bc89b30a72): free 8767138 bytes of WAL
I20260812 06:20:18.224403   500 log_reader.cc:385] T 0d49aebb3d1948368d98e8bc89b30a72: removed 1 log segments from log reader
I20260812 06:20:18.224450   500 log.cc:1079] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515613597454-348-0/minicluster-data/ts-0-root/wals/0d49aebb3d1948368d98e8bc89b30a72/wal-000000039 (ops 187-191)
I20260812 06:20:18.225844   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: LogGCOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:18.226138   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:18.235177   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.009s	user 0.005s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3152,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:18.235630   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling UndoDeltaBlockGCOp(0d49aebb3d1948368d98e8bc89b30a72): 482 bytes on disk
I20260812 06:20:18.237442   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: UndoDeltaBlockGCOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:20:18.238224   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:18.428774   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.190s	user 0.110s	sys 0.080s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":548,"lbm_read_time_us":13518,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30086,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:20:18.429394   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=14.095187
I20260812 06:20:18.487129   348 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.632s	user 1.688s	sys 0.119s
I20260812 06:20:18.490206   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.061s	user 0.041s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23566,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:18.490734   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=2.188937
I20260812 06:20:18.499699   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: FlushDeltaMemStoresOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:18.500168   588 maintenance_manager.cc:419] P 465dbf129b61424ea2d5e1532db350e7: Scheduling MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72): perf score=1.000000
I20260812 06:20:18.549105   348 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.061s	user 0.001s	sys 0.000s
I20260812 06:20:18.549702   348 tablet_server.cc:179] TabletServer@127.0.87.1:0 shutting down...
I20260812 06:20:18.621661   500 maintenance_manager.cc:643] P 465dbf129b61424ea2d5e1532db350e7: MajorDeltaCompactionOp(0d49aebb3d1948368d98e8bc89b30a72) complete. Timing: real 0.121s	user 0.092s	sys 0.029s Metrics: {"cfile_cache_hit":214,"cfile_cache_hit_bytes":8740712,"cfile_cache_miss":318,"cfile_cache_miss_bytes":16033978,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":309,"lbm_read_time_us":6102,"lbm_reads_lt_1ms":350,"lbm_write_time_us":22260,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":188288,"update_count":2500}
I20260812 06:20:18.622408   348 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:18.622817   348 tablet_replica.cc:333] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7: stopping tablet replica
I20260812 06:20:18.623051   348 raft_consensus.cc:2243] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:18.623315   348 raft_consensus.cc:2272] T 0d49aebb3d1948368d98e8bc89b30a72 P 465dbf129b61424ea2d5e1532db350e7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:18.639602   348 tablet_server.cc:196] TabletServer@127.0.87.1:0 shutdown complete.
I20260812 06:20:18.668206   348 master.cc:562] Master@127.0.87.62:43295 shutting down...
I20260812 06:20:18.671311   348 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:18.671489   348 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:18.671556   348 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1664eccb7b0b40248f82e723f9f003af: stopping tablet replica
I20260812 06:20:18.683769   348 master.cc:584] Master@127.0.87.62:43295 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5145 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:18.764138   348 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.0.87.62:41849
I20260812 06:20:18.764534   348 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:18.766448   634 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:18.766520   638 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:18.766525   635 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:18.766721   348 server_base.cc:1061] running on GCE node
I20260812 06:20:18.766857   348 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:18.766891   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:20:18.766911   348 hybrid_clock.cc:648] HybridClock initialized: now 1786515618766911 us; error 0 us; skew 500 ppm
I20260812 06:20:18.767704   348 webserver.cc:533] Webserver started at http://127.0.87.62:35827/ using document root <none> and password file <none>
I20260812 06:20:18.767866   348 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:18.767916   348 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:18.767990   348 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:18.768371   348 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/master-0-root/instance:
uuid: "d07c0d3316224c2a9fd9b33e22c947ff"
format_stamp: "Formatted at 2026-08-12 06:20:18 on dist-test-slave-vpvm"
I20260812 06:20:18.769843   348 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:18.770892   647 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:18.771167   348 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:18.771238   348 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/master-0-root
uuid: "d07c0d3316224c2a9fd9b33e22c947ff"
format_stamp: "Formatted at 2026-08-12 06:20:18 on dist-test-slave-vpvm"
I20260812 06:20:18.771296   348 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-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:20:18.782518   348 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:18.782853   348 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:18.786830   348 rpc_server.cc:307] RPC server started. Bound to: 127.0.87.62:41849
I20260812 06:20:18.788511   724 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.87.62:41849 every 8 connection(s)
I20260812 06:20:18.788961   725 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:18.790786   725 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff: Bootstrap starting.
I20260812 06:20:18.791556   725 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:18.792568   725 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff: No bootstrap required, opened a new log
I20260812 06:20:18.792989   725 raft_consensus.cc:359] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d07c0d3316224c2a9fd9b33e22c947ff" member_type: VOTER }
I20260812 06:20:18.793073   725 raft_consensus.cc:385] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:18.793097   725 raft_consensus.cc:740] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d07c0d3316224c2a9fd9b33e22c947ff, State: Initialized, Role: FOLLOWER
I20260812 06:20:18.793236   725 consensus_queue.cc:260] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [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: "d07c0d3316224c2a9fd9b33e22c947ff" member_type: VOTER }
I20260812 06:20:18.793306   725 raft_consensus.cc:399] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:18.793341   725 raft_consensus.cc:493] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:18.793390   725 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:18.794094   725 raft_consensus.cc:515] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d07c0d3316224c2a9fd9b33e22c947ff" member_type: VOTER }
I20260812 06:20:18.794215   725 leader_election.cc:304] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [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: d07c0d3316224c2a9fd9b33e22c947ff; no voters: 
I20260812 06:20:18.794397   725 leader_election.cc:290] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:18.794560   728 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:18.794776   728 raft_consensus.cc:697] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [term 1 LEADER]: Becoming Leader. State: Replica: d07c0d3316224c2a9fd9b33e22c947ff, State: Running, Role: LEADER
I20260812 06:20:18.794867   725 sys_catalog.cc:565] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:18.794924   728 consensus_queue.cc:237] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [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: "d07c0d3316224c2a9fd9b33e22c947ff" member_type: VOTER }
I20260812 06:20:18.795387   729 sys_catalog.cc:455] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d07c0d3316224c2a9fd9b33e22c947ff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d07c0d3316224c2a9fd9b33e22c947ff" member_type: VOTER } }
I20260812 06:20:18.795413   730 sys_catalog.cc:455] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [sys.catalog]: SysCatalogTable state changed. Reason: New leader d07c0d3316224c2a9fd9b33e22c947ff. Latest consensus state: current_term: 1 leader_uuid: "d07c0d3316224c2a9fd9b33e22c947ff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d07c0d3316224c2a9fd9b33e22c947ff" member_type: VOTER } }
I20260812 06:20:18.795491   729 sys_catalog.cc:458] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:18.795509   730 sys_catalog.cc:458] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:18.795747   736 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:18.796653   736 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:18.796813   348 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:18.798534   736 catalog_manager.cc:1383] Generated new cluster ID: 72876ef4437145ce906ba0ef491f86e5
I20260812 06:20:18.798599   736 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:18.859540   736 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:18.860123   736 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:18.871542   736 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff: Generated new TSK 0
I20260812 06:20:18.871731   736 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:18.925881   348 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:18.927904   757 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:18.928041   755 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:18.928083   348 server_base.cc:1061] running on GCE node
W20260812 06:20:18.927969   759 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:18.928390   348 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:18.928444   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:20:18.928465   348 hybrid_clock.cc:648] HybridClock initialized: now 1786515618928465 us; error 0 us; skew 500 ppm
I20260812 06:20:18.929283   348 webserver.cc:533] Webserver started at http://127.0.87.1:45363/ using document root <none> and password file <none>
I20260812 06:20:18.929445   348 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:18.929497   348 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:18.929590   348 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:18.930034   348 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/instance:
uuid: "ca0aa602fc3a448a950497638a4bfc62"
format_stamp: "Formatted at 2026-08-12 06:20:18 on dist-test-slave-vpvm"
I20260812 06:20:18.931576   348 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:18.932518   765 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:18.932768   348 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:18.932842   348 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root
uuid: "ca0aa602fc3a448a950497638a4bfc62"
format_stamp: "Formatted at 2026-08-12 06:20:18 on dist-test-slave-vpvm"
I20260812 06:20:18.932904   348 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-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:20:18.939931   348 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:18.940210   348 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:18.940462   348 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:18.940860   348 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:18.940894   348 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:18.940927   348 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:18.940948   348 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:18.944974   348 rpc_server.cc:307] RPC server started. Bound to: 127.0.87.1:46409
I20260812 06:20:18.946270   871 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.0.87.1:46409 every 8 connection(s)
I20260812 06:20:18.953287   872 heartbeater.cc:344] Connected to a master server at 127.0.87.62:41849
I20260812 06:20:18.953403   872 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:18.953624   872 heartbeater.cc:507] Master 127.0.87.62:41849 requested a full tablet report, sending...
I20260812 06:20:18.954324   675 ts_manager.cc:194] Registered new tserver with Master: ca0aa602fc3a448a950497638a4bfc62 (127.0.87.1:46409)
I20260812 06:20:18.954577   348 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008885236s
I20260812 06:20:18.955080   675 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54532
I20260812 06:20:18.961120   675 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54542:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:20:18.969329   810 tablet_service.cc:1511] Processing CreateTablet for tablet 435ecc0d7f7d47359227b3b2493a9a9a (DEFAULT_TABLE table=heavy-update-compaction-test [id=13fb3a6f577846f2805ce7ea68aa0421]), partition=
I20260812 06:20:18.969605   810 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 435ecc0d7f7d47359227b3b2493a9a9a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:18.971463   896 tablet_bootstrap.cc:492] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Bootstrap starting.
I20260812 06:20:18.972369   896 tablet_bootstrap.cc:654] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:18.973400   896 tablet_bootstrap.cc:492] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: No bootstrap required, opened a new log
I20260812 06:20:18.973475   896 ts_tablet_manager.cc:1403] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:20:18.973863   896 raft_consensus.cc:359] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca0aa602fc3a448a950497638a4bfc62" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 46409 } }
I20260812 06:20:18.973970   896 raft_consensus.cc:385] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:18.974013   896 raft_consensus.cc:740] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ca0aa602fc3a448a950497638a4bfc62, State: Initialized, Role: FOLLOWER
I20260812 06:20:18.974138   896 consensus_queue.cc:260] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [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: "ca0aa602fc3a448a950497638a4bfc62" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 46409 } }
I20260812 06:20:18.974221   896 raft_consensus.cc:399] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:18.974251   896 raft_consensus.cc:493] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:18.974285   896 raft_consensus.cc:3060] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:18.975008   896 raft_consensus.cc:515] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca0aa602fc3a448a950497638a4bfc62" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 46409 } }
I20260812 06:20:18.975152   896 leader_election.cc:304] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [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: ca0aa602fc3a448a950497638a4bfc62; no voters: 
I20260812 06:20:18.975330   896 leader_election.cc:290] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:18.975441   898 raft_consensus.cc:2804] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:18.975647   896 ts_tablet_manager.cc:1434] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:20:18.975677   898 raft_consensus.cc:697] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [term 1 LEADER]: Becoming Leader. State: Replica: ca0aa602fc3a448a950497638a4bfc62, State: Running, Role: LEADER
I20260812 06:20:18.975730   872 heartbeater.cc:499] Master 127.0.87.62:41849 was elected leader, sending a full tablet report...
I20260812 06:20:18.975878   898 consensus_queue.cc:237] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [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: "ca0aa602fc3a448a950497638a4bfc62" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 46409 } }
I20260812 06:20:18.977391   675 catalog_manager.cc:5719] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 reported cstate change: term changed from 0 to 1, leader changed from <none> to ca0aa602fc3a448a950497638a4bfc62 (127.0.87.1). New cstate: current_term: 1 leader_uuid: "ca0aa602fc3a448a950497638a4bfc62" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca0aa602fc3a448a950497638a4bfc62" member_type: VOTER last_known_addr { host: "127.0.87.1" port: 46409 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:19.031250   348 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.018s	sys 0.004s
I20260812 06:20:19.196753   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushMRSOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=23.023690
I20260812 06:20:19.351454   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushMRSOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.154s	user 0.108s	sys 0.043s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":801,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38032,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:20:19.352242   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling LogGCOp(435ecc0d7f7d47359227b3b2493a9a9a): free 20743880 bytes of WAL
I20260812 06:20:19.352492   774 log_reader.cc:385] T 435ecc0d7f7d47359227b3b2493a9a9a: removed 2 log segments from log reader
I20260812 06:20:19.352551   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000001 (ops 1-6)
I20260812 06:20:19.352599   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000002 (ops 7-11)
I20260812 06:20:19.357489   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: LogGCOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:19.357898   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling UndoDeltaBlockGCOp(435ecc0d7f7d47359227b3b2493a9a9a): 20513812 bytes on disk
I20260812 06:20:19.358516   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: UndoDeltaBlockGCOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:20:19.359009   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:19.373713   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":5746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.374256   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:19.516891   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.142s	user 0.104s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":325,"lbm_read_time_us":10108,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21416,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":326,"threads_started":5,"update_count":2000}
I20260812 06:20:19.517480   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=10.126437
I20260812 06:20:19.555027   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.037s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17483,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.555536   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:19.569028   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5329,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.569515   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:19.693125   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.123s	user 0.115s	sys 0.008s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":146,"lbm_read_time_us":8534,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22887,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":2000}
I20260812 06:20:19.693650   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=10.126437
I20260812 06:20:19.731957   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.038s	user 0.029s	sys 0.001s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14503,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.732545   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:19.742959   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3807,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.743551   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:19.868556   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.125s	user 0.104s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1236,"lbm_read_time_us":8925,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21903,"lbm_writes_lt_1ms":443,"mutex_wait_us":102,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:20:19.869160   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=10.126437
I20260812 06:20:19.919643   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.050s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16642,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:19.920166   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:19.933019   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4253,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:19.933542   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:20.057070   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.123s	user 0.095s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":870,"lbm_read_time_us":10414,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22031,"lbm_writes_lt_1ms":443,"mutex_wait_us":233,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:20:20.057608   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=10.126437
I20260812 06:20:20.106899   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.049s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15155,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.107503   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:20.117832   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3836,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.118364   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:20.261188   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.143s	user 0.110s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":226,"lbm_read_time_us":10309,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21977,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":57344,"update_count":2000}
I20260812 06:20:20.263900   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=10.126437
I20260812 06:20:20.309762   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.046s	user 0.028s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13165,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.310297   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:20.326087   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5891,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.326653   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:20.446079   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.119s	user 0.093s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1173,"lbm_read_time_us":7890,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22772,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:20:20.446557   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=10.126437
I20260812 06:20:20.489185   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.042s	user 0.009s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13678,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:20.489789   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:20.500563   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.501242   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushMRSOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:20.527827   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushMRSOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.026s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1246,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1382,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":5376}
I20260812 06:20:20.528431   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling LogGCOp(435ecc0d7f7d47359227b3b2493a9a9a): free 112239306 bytes of WAL
I20260812 06:20:20.528659   774 log_reader.cc:385] T 435ecc0d7f7d47359227b3b2493a9a9a: removed 11 log segments from log reader
I20260812 06:20:20.528718   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000003 (ops 12-16)
I20260812 06:20:20.528761   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000004 (ops 17-21)
I20260812 06:20:20.528793   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000005 (ops 22-26)
I20260812 06:20:20.528827   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000006 (ops 27-31)
I20260812 06:20:20.528857   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000007 (ops 32-36)
I20260812 06:20:20.528885   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000008 (ops 37-41)
I20260812 06:20:20.528913   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000009 (ops 42-46)
I20260812 06:20:20.528944   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000010 (ops 47-50)
I20260812 06:20:20.528975   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000011 (ops 51-55)
I20260812 06:20:20.529003   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000012 (ops 56-60)
I20260812 06:20:20.529031   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000013 (ops 61-65)
I20260812 06:20:20.552546   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: LogGCOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:20:20.552942   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling UndoDeltaBlockGCOp(435ecc0d7f7d47359227b3b2493a9a9a): 448 bytes on disk
I20260812 06:20:20.553350   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: UndoDeltaBlockGCOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:20:20.553831   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=3.181125
I20260812 06:20:20.570503   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4304,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:20.571024   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling LogGCOp(435ecc0d7f7d47359227b3b2493a9a9a): free 12017932 bytes of WAL
I20260812 06:20:20.571273   774 log_reader.cc:385] T 435ecc0d7f7d47359227b3b2493a9a9a: removed 1 log segments from log reader
I20260812 06:20:20.571326   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000014 (ops 66-70)
I20260812 06:20:20.573277   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: LogGCOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:20.573624   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:20.583575   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3190,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:20.584143   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:20.757462   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.173s	user 0.126s	sys 0.042s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":103,"lbm_read_time_us":12007,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31071,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7680,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:20:20.758025   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=14.095187
I20260812 06:20:20.805826   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.048s	user 0.024s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17156,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:20.806334   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:20.817562   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:20.818215   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:20.961189   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.143s	user 0.115s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":298,"lbm_read_time_us":9577,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26236,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":63616,"update_count":2500}
I20260812 06:20:20.961812   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=11.118625
I20260812 06:20:20.993319   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.031s	user 0.025s	sys 0.003s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13803,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:20.993992   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:21.011862   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5778,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.012406   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:21.154170   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.142s	user 0.105s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1064,"lbm_read_time_us":9421,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22548,"lbm_writes_lt_1ms":443,"mutex_wait_us":300,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22784,"update_count":2000}
I20260812 06:20:21.154830   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=11.118625
I20260812 06:20:21.196843   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.042s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14149,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:21.197456   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:21.222229   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.025s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4561,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.222788   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:21.232704   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.233212   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:21.411020   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.178s	user 0.120s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":627,"lbm_read_time_us":11600,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28726,"lbm_writes_lt_1ms":543,"mutex_wait_us":279,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:20:21.411479   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=14.095187
I20260812 06:20:21.465708   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.054s	user 0.017s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18997,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.466369   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:21.476538   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3954,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.477080   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:21.650542   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.173s	user 0.100s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":391,"lbm_read_time_us":11122,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25993,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:20:21.651134   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=14.095187
I20260812 06:20:21.704022   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.053s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17489,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:21.704597   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:21.714628   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3765,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.715063   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:21.881268   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.166s	user 0.120s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":10959,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26123,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:20:21.881969   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=11.118625
I20260812 06:20:21.912631   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.030s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12332,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:21.913110   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:21.938050   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.025s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4455,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:21.938544   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:21.948494   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3595,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:21.948993   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushMRSOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:21.986722   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushMRSOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.038s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1226,"drs_written":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2238,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:21.987411   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling LogGCOp(435ecc0d7f7d47359227b3b2493a9a9a): free 121006436 bytes of WAL
I20260812 06:20:21.987658   774 log_reader.cc:385] T 435ecc0d7f7d47359227b3b2493a9a9a: removed 12 log segments from log reader
I20260812 06:20:21.987716   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000015 (ops 71-75)
I20260812 06:20:21.987763   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000016 (ops 76-80)
I20260812 06:20:21.987797   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000017 (ops 81-85)
I20260812 06:20:21.987818   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000018 (ops 86-90)
I20260812 06:20:21.987844   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000019 (ops 91-94)
I20260812 06:20:21.987875   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000020 (ops 95-99)
I20260812 06:20:21.987907   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000021 (ops 100-104)
I20260812 06:20:21.987942   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000022 (ops 105-109)
I20260812 06:20:21.987970   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000023 (ops 110-114)
I20260812 06:20:21.987998   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000024 (ops 115-119)
I20260812 06:20:21.988027   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000025 (ops 120-124)
I20260812 06:20:21.988060   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000026 (ops 125-129)
I20260812 06:20:22.014447   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: LogGCOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.027s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:20:22.014950   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling UndoDeltaBlockGCOp(435ecc0d7f7d47359227b3b2493a9a9a): 482 bytes on disk
I20260812 06:20:22.015411   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: UndoDeltaBlockGCOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:20:22.015934   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=3.181125
I20260812 06:20:22.038704   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.023s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6316,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:22.039165   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:22.049365   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3767,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:22.049831   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:22.293869   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.244s	user 0.170s	sys 0.060s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020843,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":564,"dirs.run_cpu_time_us":456,"dirs.run_wall_time_us":2548,"lbm_read_time_us":14527,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37106,"lbm_writes_lt_1ms":743,"mutex_wait_us":68,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6656,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:20:22.294540   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=18.063937
I20260812 06:20:22.353848   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.058s	user 0.010s	sys 0.043s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":24502,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:20:22.354354   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:22.369761   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.015s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5587,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.370337   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:22.552062   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.182s	user 0.105s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":869,"lbm_read_time_us":12732,"lbm_reads_lt_1ms":672,"lbm_write_time_us":29715,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:20:22.552729   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=14.095187
I20260812 06:20:22.607224   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.054s	user 0.041s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23910,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:22.607834   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:22.619367   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4261,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.619854   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:22.776798   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.157s	user 0.121s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1178,"lbm_read_time_us":9531,"lbm_reads_lt_1ms":564,"lbm_write_time_us":25991,"lbm_writes_lt_1ms":543,"mutex_wait_us":352,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22784,"update_count":2500}
I20260812 06:20:22.777398   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=14.095187
I20260812 06:20:22.831223   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.054s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19015,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:22.831808   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:22.847257   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.015s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5775,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.847911   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:23.025388   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.177s	user 0.105s	sys 0.066s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":817,"lbm_read_time_us":13284,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28395,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22144,"update_count":2500}
I20260812 06:20:23.025995   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=14.095187
I20260812 06:20:23.078231   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.052s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16421,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.078806   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:23.089180   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3792,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.089794   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:23.265906   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.176s	user 0.116s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":935,"lbm_read_time_us":11323,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27043,"lbm_writes_lt_1ms":543,"mutex_wait_us":282,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:20:23.266497   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=14.095187
I20260812 06:20:23.321789   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.055s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19991,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:23.322422   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:23.332732   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3881,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.333191   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushMRSOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:23.374056   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushMRSOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.041s	user 0.020s	sys 0.007s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":1282,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1458,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:23.374850   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling LogGCOp(435ecc0d7f7d47359227b3b2493a9a9a): free 120553586 bytes of WAL
I20260812 06:20:23.375088   774 log_reader.cc:385] T 435ecc0d7f7d47359227b3b2493a9a9a: removed 12 log segments from log reader
I20260812 06:20:23.375134   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000027 (ops 130-134)
I20260812 06:20:23.375164   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000028 (ops 135-138)
I20260812 06:20:23.375195   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000029 (ops 139-143)
I20260812 06:20:23.375226   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000030 (ops 144-148)
I20260812 06:20:23.375258   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000031 (ops 149-153)
I20260812 06:20:23.375291   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000032 (ops 154-158)
I20260812 06:20:23.375324   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000033 (ops 159-162)
I20260812 06:20:23.375355   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000034 (ops 163-167)
I20260812 06:20:23.375387   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000035 (ops 168-172)
I20260812 06:20:23.375419   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000036 (ops 173-177)
I20260812 06:20:23.375452   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000037 (ops 178-182)
I20260812 06:20:23.375484   774 log.cc:1079] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: Deleting log segment in path: /tmp/dist-test-taskjvu4n7/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515613597454-348-0/minicluster-data/ts-0-root/wals/435ecc0d7f7d47359227b3b2493a9a9a/wal-000000038 (ops 183-187)
I20260812 06:20:23.395677   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: LogGCOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.021s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:20:23.396157   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling UndoDeltaBlockGCOp(435ecc0d7f7d47359227b3b2493a9a9a): 447 bytes on disk
I20260812 06:20:23.396720   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: UndoDeltaBlockGCOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:20:23.397294   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:23.414983   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.018s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.415407   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:23.425359   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.425838   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:23.632308   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.206s	user 0.131s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020743,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":785,"lbm_read_time_us":14172,"lbm_reads_lt_1ms":774,"lbm_write_time_us":31596,"lbm_writes_lt_1ms":743,"mutex_wait_us":44,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":74496,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:20:23.633252   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=16.079562
I20260812 06:20:23.688283   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.055s	user 0.028s	sys 0.021s Metrics: {"bytes_written":17845754,"delete_count":0,"lbm_write_time_us":23346,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":436,"reinsert_count":0,"update_count":2175}
I20260812 06:20:23.688745   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.196750
I20260812 06:20:23.698561   348 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.667s	user 1.662s	sys 0.202s
I20260812 06:20:23.699795   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.011s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3077034,"delete_count":0,"lbm_write_time_us":2916,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:20:23.700276   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=2.188937
I20260812 06:20:23.708760   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: FlushDeltaMemStoresOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.008s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3332,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:23.709316   873 maintenance_manager.cc:419] P ca0aa602fc3a448a950497638a4bfc62: Scheduling MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a): perf score=1.000000
I20260812 06:20:23.771472   348 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.072s	user 0.001s	sys 0.000s
I20260812 06:20:23.771983   348 tablet_server.cc:179] TabletServer@127.0.87.1:0 shutting down...
I20260812 06:20:23.853894   774 maintenance_manager.cc:643] P ca0aa602fc3a448a950497638a4bfc62: MajorDeltaCompactionOp(435ecc0d7f7d47359227b3b2493a9a9a) complete. Timing: real 0.144s	user 0.116s	sys 0.028s Metrics: {"cfile_cache_hit":202,"cfile_cache_hit_bytes":8209116,"cfile_cache_miss":431,"cfile_cache_miss_bytes":20709072,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":456,"lbm_read_time_us":8553,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26079,"lbm_writes_lt_1ms":643,"mutex_wait_us":78,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":3000}
I20260812 06:20:23.854498   348 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:23.854702   348 tablet_replica.cc:333] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62: stopping tablet replica
I20260812 06:20:23.854887   348 raft_consensus.cc:2243] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:23.855082   348 raft_consensus.cc:2272] T 435ecc0d7f7d47359227b3b2493a9a9a P ca0aa602fc3a448a950497638a4bfc62 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:23.868466   348 tablet_server.cc:196] TabletServer@127.0.87.1:0 shutdown complete.
I20260812 06:20:23.905984   348 master.cc:562] Master@127.0.87.62:41849 shutting down...
I20260812 06:20:23.908991   348 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:23.909168   348 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:23.909240   348 tablet_replica.cc:333] T 00000000000000000000000000000000 P d07c0d3316224c2a9fd9b33e22c947ff: stopping tablet replica
I20260812 06:20:23.921563   348 master.cc:584] Master@127.0.87.62:41849 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5238 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10385 ms total)

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