[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:21.544421 31453 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.183.126:41981
I20260812 06:18:21.545684 31453 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:21.546432 31453 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:21.556684 31461 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:21.556811 31459 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:21.556946 31453 server_base.cc:1061] running on GCE node
W20260812 06:18:21.557250 31458 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:21.558182 31453 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:21.558377 31453 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:21.558470 31453 hybrid_clock.cc:648] HybridClock initialized: now 1786515501558466 us; error 0 us; skew 500 ppm
I20260812 06:18:21.562100 31453 webserver.cc:533] Webserver started at http://127.30.183.126:34959/ using document root <none> and password file <none>
I20260812 06:18:21.562966 31453 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:21.563091 31453 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:21.563392 31453 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:21.566803 31453 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/master-0-root/instance:
uuid: "e0632c299b2b472dbe4ac355fed79491"
format_stamp: "Formatted at 2026-08-12 06:18:21 on dist-test-slave-rgb1"
I20260812 06:18:21.573567 31453 fs_manager.cc:696] Time spent creating directory manager: real 0.006s	user 0.007s	sys 0.001s
I20260812 06:18:21.576864 31466 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:21.579269 31453 fs_manager.cc:730] Time spent opening block manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:18:21.580016 31453 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/master-0-root
uuid: "e0632c299b2b472dbe4ac355fed79491"
format_stamp: "Formatted at 2026-08-12 06:18:21 on dist-test-slave-rgb1"
I20260812 06:18:21.580684 31453 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:21.617420 31453 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:21.618641 31453 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:21.619208 31453 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:21.632949 31453 rpc_server.cc:307] RPC server started. Bound to: 127.30.183.126:41981
I20260812 06:18:21.632993 31524 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.183.126:41981 every 8 connection(s)
I20260812 06:18:21.635816 31525 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:21.644605 31525 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491: Bootstrap starting.
I20260812 06:18:21.648803 31525 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:21.650211 31525 log.cc:826] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:21.653496 31525 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491: No bootstrap required, opened a new log
I20260812 06:18:21.656967 31525 raft_consensus.cc:359] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e0632c299b2b472dbe4ac355fed79491" member_type: VOTER }
I20260812 06:18:21.657195 31525 raft_consensus.cc:385] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:21.657240 31525 raft_consensus.cc:740] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e0632c299b2b472dbe4ac355fed79491, State: Initialized, Role: FOLLOWER
I20260812 06:18:21.658210 31525 consensus_queue.cc:260] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [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: "e0632c299b2b472dbe4ac355fed79491" member_type: VOTER }
I20260812 06:18:21.658565 31525 raft_consensus.cc:399] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:21.658630 31525 raft_consensus.cc:493] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:21.658797 31525 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:21.660367 31525 raft_consensus.cc:515] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e0632c299b2b472dbe4ac355fed79491" member_type: VOTER }
I20260812 06:18:21.661849 31525 leader_election.cc:304] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [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: e0632c299b2b472dbe4ac355fed79491; no voters: 
I20260812 06:18:21.662674 31525 leader_election.cc:290] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:21.662902 31528 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:21.663450 31528 raft_consensus.cc:697] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [term 1 LEADER]: Becoming Leader. State: Replica: e0632c299b2b472dbe4ac355fed79491, State: Running, Role: LEADER
I20260812 06:18:21.664002 31528 consensus_queue.cc:237] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [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: "e0632c299b2b472dbe4ac355fed79491" member_type: VOTER }
I20260812 06:18:21.664134 31525 sys_catalog.cc:565] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:21.666285 31530 sys_catalog.cc:455] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e0632c299b2b472dbe4ac355fed79491. Latest consensus state: current_term: 1 leader_uuid: "e0632c299b2b472dbe4ac355fed79491" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e0632c299b2b472dbe4ac355fed79491" member_type: VOTER } }
I20260812 06:18:21.666328 31529 sys_catalog.cc:455] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e0632c299b2b472dbe4ac355fed79491" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e0632c299b2b472dbe4ac355fed79491" member_type: VOTER } }
I20260812 06:18:21.666486 31530 sys_catalog.cc:458] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:21.666483 31529 sys_catalog.cc:458] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:21.667212 31542 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:21.667804 31453 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:21.671352 31542 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:21.680729 31542 catalog_manager.cc:1383] Generated new cluster ID: 84672344362e47829befebede79853c8
I20260812 06:18:21.681259 31542 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:21.699970 31542 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:21.701032 31542 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:21.707861 31542 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491: Generated new TSK 0
I20260812 06:18:21.709018 31542 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:21.733522 31453 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:21.737462 31551 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:21.737555 31550 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:21.737540 31553 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:21.737844 31453 server_base.cc:1061] running on GCE node
I20260812 06:18:21.738044 31453 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:21.738127 31453 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:21.738154 31453 hybrid_clock.cc:648] HybridClock initialized: now 1786515501738154 us; error 0 us; skew 500 ppm
I20260812 06:18:21.739945 31453 webserver.cc:533] Webserver started at http://127.30.183.65:35707/ using document root <none> and password file <none>
I20260812 06:18:21.740332 31453 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:21.740430 31453 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:21.740623 31453 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:21.741550 31453 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/instance:
uuid: "3449ca47d21e4736b5badf72ef0f5895"
format_stamp: "Formatted at 2026-08-12 06:18:21 on dist-test-slave-rgb1"
I20260812 06:18:21.744786 31453 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:18:21.746476 31560 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:21.746815 31453 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:21.746898 31453 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root
uuid: "3449ca47d21e4736b5badf72ef0f5895"
format_stamp: "Formatted at 2026-08-12 06:18:21 on dist-test-slave-rgb1"
I20260812 06:18:21.747016 31453 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:21.756116 31453 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:21.757184 31453 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:21.758826 31453 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:21.760175 31453 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:21.760250 31453 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:21.760306 31453 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:21.760321 31453 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:21.770282 31453 rpc_server.cc:307] RPC server started. Bound to: 127.30.183.65:46793
I20260812 06:18:21.770303 31631 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.183.65:46793 every 8 connection(s)
I20260812 06:18:21.797659 31632 heartbeater.cc:344] Connected to a master server at 127.30.183.126:41981
I20260812 06:18:21.797984 31632 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:21.798614 31632 heartbeater.cc:507] Master 127.30.183.126:41981 requested a full tablet report, sending...
I20260812 06:18:21.803275 31484 ts_manager.cc:194] Registered new tserver with Master: 3449ca47d21e4736b5badf72ef0f5895 (127.30.183.65:46793)
I20260812 06:18:21.804121 31453 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.033063053s
I20260812 06:18:21.805420 31484 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56178
I20260812 06:18:21.827811 31484 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56190:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:21.852411 31591 tablet_service.cc:1511] Processing CreateTablet for tablet 7cbe438fbe984de89f51233a4c4c1c53 (DEFAULT_TABLE table=heavy-update-compaction-test [id=055d3cd1fea94544ab8344002c3aa81b]), partition=
I20260812 06:18:21.853034 31591 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7cbe438fbe984de89f51233a4c4c1c53. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:21.856599 31644 tablet_bootstrap.cc:492] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Bootstrap starting.
I20260812 06:18:21.857833 31644 tablet_bootstrap.cc:654] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:21.862100 31644 tablet_bootstrap.cc:492] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: No bootstrap required, opened a new log
I20260812 06:18:21.862435 31644 ts_tablet_manager.cc:1403] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Time spent bootstrapping tablet: real 0.006s	user 0.004s	sys 0.000s
I20260812 06:18:21.864032 31644 raft_consensus.cc:359] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3449ca47d21e4736b5badf72ef0f5895" member_type: VOTER last_known_addr { host: "127.30.183.65" port: 46793 } }
I20260812 06:18:21.864177 31644 raft_consensus.cc:385] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:21.864202 31644 raft_consensus.cc:740] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3449ca47d21e4736b5badf72ef0f5895, State: Initialized, Role: FOLLOWER
I20260812 06:18:21.864439 31644 consensus_queue.cc:260] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [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: "3449ca47d21e4736b5badf72ef0f5895" member_type: VOTER last_known_addr { host: "127.30.183.65" port: 46793 } }
I20260812 06:18:21.864537 31644 raft_consensus.cc:399] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:21.864645 31644 raft_consensus.cc:493] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:21.864684 31644 raft_consensus.cc:3060] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:21.865895 31644 raft_consensus.cc:515] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3449ca47d21e4736b5badf72ef0f5895" member_type: VOTER last_known_addr { host: "127.30.183.65" port: 46793 } }
I20260812 06:18:21.866060 31644 leader_election.cc:304] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [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: 3449ca47d21e4736b5badf72ef0f5895; no voters: 
I20260812 06:18:21.866302 31644 leader_election.cc:290] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:21.866663 31646 raft_consensus.cc:2804] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:21.866858 31644 ts_tablet_manager.cc:1434] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Time spent starting tablet: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:18:21.866981 31646 raft_consensus.cc:697] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [term 1 LEADER]: Becoming Leader. State: Replica: 3449ca47d21e4736b5badf72ef0f5895, State: Running, Role: LEADER
I20260812 06:18:21.867195 31646 consensus_queue.cc:237] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [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: "3449ca47d21e4736b5badf72ef0f5895" member_type: VOTER last_known_addr { host: "127.30.183.65" port: 46793 } }
I20260812 06:18:21.867688 31632 heartbeater.cc:499] Master 127.30.183.126:41981 was elected leader, sending a full tablet report...
I20260812 06:18:21.871966 31484 catalog_manager.cc:5719] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3449ca47d21e4736b5badf72ef0f5895 (127.30.183.65). New cstate: current_term: 1 leader_uuid: "3449ca47d21e4736b5badf72ef0f5895" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3449ca47d21e4736b5badf72ef0f5895" member_type: VOTER last_known_addr { host: "127.30.183.65" port: 46793 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:21.979061 31453 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.093s	user 0.030s	sys 0.017s
I20260812 06:18:22.022225 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushMRSOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=3.179940
I20260812 06:18:22.133384 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushMRSOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.110s	user 0.085s	sys 0.023s Metrics: {"bytes_written":7794836,"cfile_init":1,"compiler_manager_pool.queue_time_us":106,"delete_count":0,"dirs.queue_time_us":135,"dirs.run_cpu_time_us":446,"dirs.run_wall_time_us":1357,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":21167,"lbm_writes_lt_1ms":257,"peak_mem_usage":0,"reinsert_count":0,"rows_written":101,"update_count":950}
I20260812 06:18:22.136222 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:22.279150 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.142s	user 0.101s	sys 0.040s Metrics: {"cfile_cache_miss":221,"cfile_cache_miss_bytes":11934197,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1123,"lbm_read_time_us":7588,"lbm_reads_lt_1ms":253,"lbm_write_time_us":25369,"lbm_writes_lt_1ms":233,"peak_mem_usage":24385450,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":613,"threads_started":5,"update_count":950}
I20260812 06:18:22.279762 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=6.157687
I20260812 06:18:22.318328 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.038s	user 0.025s	sys 0.001s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12179,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":1000}
I20260812 06:18:22.318960 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling UndoDeltaBlockGCOp(7cbe438fbe984de89f51233a4c4c1c53): 411733 bytes on disk
I20260812 06:18:22.319507 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: UndoDeltaBlockGCOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:22.319945 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:22.331269 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.331928 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:22.463956 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.132s	user 0.080s	sys 0.049s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446970,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1532,"lbm_read_time_us":7344,"lbm_reads_lt_1ms":372,"lbm_write_time_us":23464,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:18:22.464666 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=7.149875
I20260812 06:18:22.503801 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.039s	user 0.026s	sys 0.005s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":14097,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:22.504436 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:22.519125 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4958,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:22.519881 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:22.659394 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.139s	user 0.126s	sys 0.004s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446961,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":882,"lbm_read_time_us":9878,"lbm_reads_lt_1ms":372,"lbm_write_time_us":26148,"lbm_writes_lt_1ms":343,"mutex_wait_us":1,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":1500}
I20260812 06:18:22.660270 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=7.149875
I20260812 06:18:22.691483 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.031s	user 0.024s	sys 0.004s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12929,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:22.692174 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:22.717903 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.025s	user 0.021s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":9842,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:22.718556 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:22.850178 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.131s	user 0.096s	sys 0.032s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446961,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":659,"lbm_read_time_us":9394,"lbm_reads_lt_1ms":368,"lbm_write_time_us":22946,"lbm_writes_lt_1ms":343,"mutex_wait_us":100,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":1500}
I20260812 06:18:22.850883 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=7.149875
I20260812 06:18:22.890807 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.040s	user 0.029s	sys 0.008s Metrics: {"bytes_written":8451224,"delete_count":0,"lbm_write_time_us":16967,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":208,"reinsert_count":0,"update_count":1030}
I20260812 06:18:22.891588 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:22.912133 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.020s	user 0.005s	sys 0.012s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":7241,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:22.913220 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:23.046931 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.133s	user 0.097s	sys 0.033s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446966,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":214,"lbm_read_time_us":8437,"lbm_reads_lt_1ms":372,"lbm_write_time_us":27090,"lbm_writes_lt_1ms":343,"mutex_wait_us":65,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:18:23.047933 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=10.126437
I20260812 06:18:23.090493 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.042s	user 0.032s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17882,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.091032 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:23.223642 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.132s	user 0.093s	sys 0.031s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16446853,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":861,"lbm_read_time_us":8132,"lbm_reads_lt_1ms":363,"lbm_write_time_us":26087,"lbm_writes_lt_1ms":343,"mutex_wait_us":335,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1500}
I20260812 06:18:23.224459 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=10.126437
I20260812 06:18:23.285849 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.061s	user 0.028s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19457,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.286473 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:23.300526 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.301479 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:23.464427 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.163s	user 0.129s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1169,"lbm_read_time_us":9896,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31504,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22912,"update_count":2000}
I20260812 06:18:23.465377 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=10.126437
I20260812 06:18:23.534037 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.068s	user 0.024s	sys 0.043s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":25236,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.534782 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:23.553423 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.018s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6584,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.554378 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:23.742200 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.188s	user 0.116s	sys 0.072s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":216,"lbm_read_time_us":12827,"lbm_reads_lt_1ms":464,"lbm_write_time_us":33196,"lbm_writes_lt_1ms":443,"mutex_wait_us":75,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2000}
I20260812 06:18:23.744344 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=10.126437
I20260812 06:18:23.795924 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.051s	user 0.027s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":25556,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.796873 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:23.838915 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.042s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7719,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.839857 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:23.860926 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.021s	user 0.013s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8113,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.861680 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushMRSOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:23.909287 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushMRSOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.047s	user 0.042s	sys 0.001s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":332,"dirs.run_wall_time_us":1857,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1932,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:23.911142 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling UndoDeltaBlockGCOp(7cbe438fbe984de89f51233a4c4c1c53): 462 bytes on disk
I20260812 06:18:23.913316 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: UndoDeltaBlockGCOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:18:23.914785 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling LogGCOp(7cbe438fbe984de89f51233a4c4c1c53): free 120965283 bytes of WAL
I20260812 06:18:23.915433 31566 log_reader.cc:385] T 7cbe438fbe984de89f51233a4c4c1c53: removed 12 log segments from log reader
I20260812 06:18:23.915566 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000001 (ops 1-6)
I20260812 06:18:23.915669 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000002 (ops 7-11)
I20260812 06:18:23.915877 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000003 (ops 12-16)
I20260812 06:18:23.916016 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000004 (ops 17-20)
I20260812 06:18:23.916069 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000005 (ops 21-25)
I20260812 06:18:23.916110 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000006 (ops 26-30)
I20260812 06:18:23.916145 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000007 (ops 31-35)
I20260812 06:18:23.916182 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000008 (ops 36-40)
I20260812 06:18:23.916220 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000009 (ops 41-45)
I20260812 06:18:23.916258 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000010 (ops 46-50)
I20260812 06:18:23.916297 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000011 (ops 51-55)
I20260812 06:18:23.916339 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000012 (ops 56-60)
I20260812 06:18:23.944196 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: LogGCOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:23.944748 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=3.181125
I20260812 06:18:23.978626 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.034s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6636,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:23.979460 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:23.992174 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4620,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.992846 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:24.260633 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.268s	user 0.190s	sys 0.077s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32856966,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":530,"lbm_read_time_us":16530,"lbm_reads_lt_1ms":775,"lbm_write_time_us":46309,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15616,"thread_start_us":336,"threads_started":5,"update_count":3500}
I20260812 06:18:24.261413 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=14.095187
I20260812 06:18:24.327337 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.064s	user 0.058s	sys 0.003s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":27838,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.328256 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:24.351426 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.023s	user 0.013s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7858,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.352336 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:24.551877 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.199s	user 0.141s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651790,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":445,"lbm_read_time_us":14178,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33966,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:18:24.552500 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=14.095187
I20260812 06:18:24.622188 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.069s	user 0.035s	sys 0.032s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":30892,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.623003 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:24.637795 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5685,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.638368 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:24.846848 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.208s	user 0.151s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651792,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":345,"lbm_read_time_us":12526,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35168,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":97152,"update_count":2500}
I20260812 06:18:24.847672 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=14.095187
I20260812 06:18:24.945708 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.098s	user 0.054s	sys 0.039s Metrics: {"bytes_written":16409931,"delete_count":0,"lbm_write_time_us":35675,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.946900 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:24.967787 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.969066 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:25.167833 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.198s	user 0.134s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651823,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":14512,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33278,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2500}
I20260812 06:18:25.168777 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=11.118625
I20260812 06:18:25.216413 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.047s	user 0.026s	sys 0.017s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19326,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:25.216948 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:25.228796 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4689,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.229344 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:25.416834 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.187s	user 0.120s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549375,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":866,"lbm_read_time_us":8288,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28694,"lbm_writes_lt_1ms":443,"mutex_wait_us":162,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:25.418110 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=14.095187
I20260812 06:18:25.477151 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.059s	user 0.047s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26792,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.477788 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:25.494558 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.017s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5977,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.495412 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:25.664263 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.168s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":293,"lbm_read_time_us":10383,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35355,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2500}
I20260812 06:18:25.664959 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=11.118625
I20260812 06:18:25.715705 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.051s	user 0.035s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":22509,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:25.716647 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:25.739630 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.022s	user 0.016s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7038,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":450}
I20260812 06:18:25.740312 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushMRSOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:25.805775 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushMRSOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.065s	user 0.036s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":295,"dirs.run_wall_time_us":2308,"drs_written":1,"lbm_read_time_us":112,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2890,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:25.807276 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling LogGCOp(7cbe438fbe984de89f51233a4c4c1c53): free 124710300 bytes of WAL
I20260812 06:18:25.807653 31566 log_reader.cc:385] T 7cbe438fbe984de89f51233a4c4c1c53: removed 12 log segments from log reader
I20260812 06:18:25.807710 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000013 (ops 61-65)
I20260812 06:18:25.807857 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000014 (ops 66-70)
I20260812 06:18:25.807917 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000015 (ops 71-75)
I20260812 06:18:25.807940 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000016 (ops 76-80)
I20260812 06:18:25.808228 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000017 (ops 81-85)
I20260812 06:18:25.808341 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000018 (ops 86-90)
I20260812 06:18:25.808393 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000019 (ops 91-95)
I20260812 06:18:25.808441 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000020 (ops 96-100)
I20260812 06:18:25.808488 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000021 (ops 101-105)
I20260812 06:18:25.808548 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000022 (ops 106-110)
I20260812 06:18:25.808625 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000023 (ops 111-115)
I20260812 06:18:25.808671 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000024 (ops 116-120)
I20260812 06:18:25.839828 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: LogGCOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:25.840842 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling UndoDeltaBlockGCOp(7cbe438fbe984de89f51233a4c4c1c53): 483 bytes on disk
I20260812 06:18:25.842027 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: UndoDeltaBlockGCOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.001s	user 0.000s	sys 0.001s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:18:25.842898 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=7.149875
I20260812 06:18:25.872866 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.030s	user 0.021s	sys 0.008s Metrics: {"bytes_written":8574299,"delete_count":0,"lbm_write_time_us":11437,"lbm_writes_lt_1ms":212,"reinsert_count":0,"update_count":1045}
I20260812 06:18:25.873536 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling LogGCOp(7cbe438fbe984de89f51233a4c4c1c53): free 12017925 bytes of WAL
I20260812 06:18:25.873823 31566 log_reader.cc:385] T 7cbe438fbe984de89f51233a4c4c1c53: removed 1 log segments from log reader
I20260812 06:18:25.873893 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000025 (ops 121-125)
I20260812 06:18:25.877635 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: LogGCOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:25.878638 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:25.907131 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.028s	user 0.012s	sys 0.004s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":7115,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:18:25.908630 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:26.143942 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.235s	user 0.161s	sys 0.066s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32856844,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":265,"lbm_read_time_us":18694,"lbm_reads_lt_1ms":766,"lbm_write_time_us":45484,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":19968,"thread_start_us":124,"threads_started":1,"update_count":3500}
I20260812 06:18:26.145293 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=15.087375
I20260812 06:18:26.227281 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.081s	user 0.039s	sys 0.025s Metrics: {"bytes_written":16820146,"delete_count":0,"lbm_write_time_us":30944,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:26.227833 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=6.157687
I20260812 06:18:26.257694 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.030s	user 0.027s	sys 0.000s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":12255,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:26.258467 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:26.442718 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.184s	user 0.154s	sys 0.028s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754209,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":144,"lbm_read_time_us":11143,"lbm_reads_lt_1ms":664,"lbm_write_time_us":37424,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:26.443459 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=14.095187
I20260812 06:18:26.500742 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.057s	user 0.028s	sys 0.028s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":25477,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.501860 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:26.519989 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.018s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6923,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.520800 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:26.716795 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.196s	user 0.137s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651790,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":511,"lbm_read_time_us":13306,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35472,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:18:26.717602 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=14.095187
I20260812 06:18:26.774907 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.057s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24430,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.775451 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:26.944845 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.169s	user 0.111s	sys 0.050s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20549263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":246,"lbm_read_time_us":10195,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29659,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.945623 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=14.095187
I20260812 06:18:27.006587 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.061s	user 0.040s	sys 0.013s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23826,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.007709 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:27.024948 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.016s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5986,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.025545 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:27.233019 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.207s	user 0.153s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":287,"lbm_read_time_us":14126,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32663,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":51712,"update_count":2500}
I20260812 06:18:27.233915 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=14.095187
I20260812 06:18:27.294955 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.061s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":22739,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.296070 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:27.308426 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4458,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.309044 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:27.490979 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.182s	user 0.148s	sys 0.030s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1398,"lbm_read_time_us":11066,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36470,"lbm_writes_lt_1ms":543,"mutex_wait_us":394,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:27.491770 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=11.118625
I20260812 06:18:27.535245 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.043s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18419,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:27.536090 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:27.556178 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.020s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6513,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:27.556900 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushMRSOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:27.604460 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushMRSOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.047s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":108,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":2156,"drs_written":1,"lbm_read_time_us":146,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2346,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:27.605840 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling UndoDeltaBlockGCOp(7cbe438fbe984de89f51233a4c4c1c53): 493 bytes on disk
I20260812 06:18:27.606777 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: UndoDeltaBlockGCOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:18:27.607720 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=3.181125
I20260812 06:18:27.622390 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.014s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5828,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:27.622908 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling LogGCOp(7cbe438fbe984de89f51233a4c4c1c53): free 129320769 bytes of WAL
I20260812 06:18:27.623145 31566 log_reader.cc:385] T 7cbe438fbe984de89f51233a4c4c1c53: removed 13 log segments from log reader
I20260812 06:18:27.623188 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000026 (ops 126-130)
I20260812 06:18:27.623217 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000027 (ops 131-135)
I20260812 06:18:27.623293 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000028 (ops 136-140)
I20260812 06:18:27.623338 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000029 (ops 141-145)
I20260812 06:18:27.623400 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000030 (ops 146-150)
I20260812 06:18:27.623443 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000031 (ops 151-154)
I20260812 06:18:27.623483 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000032 (ops 155-159)
I20260812 06:18:27.623524 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000033 (ops 160-164)
I20260812 06:18:27.623564 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000034 (ops 165-168)
I20260812 06:18:27.623605 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000035 (ops 169-173)
I20260812 06:18:27.623644 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000036 (ops 174-178)
I20260812 06:18:27.623683 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000037 (ops 179-183)
I20260812 06:18:27.623726 31566 log.cc:1079] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/7cbe438fbe984de89f51233a4c4c1c53/wal-000000038 (ops 184-188)
I20260812 06:18:27.655265 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: LogGCOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:27.656466 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:27.685277 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.028s	user 0.007s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4458,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.685917 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:27.698266 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4924,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:27.699259 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:27.959722 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.260s	user 0.164s	sys 0.096s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32856956,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":953,"lbm_read_time_us":17250,"lbm_reads_lt_1ms":775,"lbm_write_time_us":48806,"lbm_writes_lt_1ms":743,"mutex_wait_us":78,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":23168,"thread_start_us":166,"threads_started":1,"update_count":3500}
I20260812 06:18:27.961282 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=14.095187
I20260812 06:18:27.997910 31453 heavy-update-compaction-itest.cc:229] Time spent updating: real 6.019s	user 2.205s	sys 0.212s
I20260812 06:18:28.016745 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.055s	user 0.051s	sys 0.004s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25476,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.017371 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=2.188937
I20260812 06:18:28.030395 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: FlushDeltaMemStoresOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5276,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.030913 31633 maintenance_manager.cc:419] P 3449ca47d21e4736b5badf72ef0f5895: Scheduling MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53): perf score=1.000000
I20260812 06:18:28.052755 31453 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.054s	user 0.004s	sys 0.004s
I20260812 06:18:28.053540 31453 tablet_server.cc:179] TabletServer@127.30.183.65:0 shutting down...
I20260812 06:18:28.184957 31566 maintenance_manager.cc:643] P 3449ca47d21e4736b5badf72ef0f5895: MajorDeltaCompactionOp(7cbe438fbe984de89f51233a4c4c1c53) complete. Timing: real 0.154s	user 0.097s	sys 0.056s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4139495,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512297,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":309,"lbm_read_time_us":8945,"lbm_reads_lt_1ms":518,"lbm_write_time_us":26841,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:18:28.185976 31453 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:28.186427 31453 tablet_replica.cc:333] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895: stopping tablet replica
I20260812 06:18:28.186683 31453 raft_consensus.cc:2243] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:28.187091 31453 raft_consensus.cc:2272] T 7cbe438fbe984de89f51233a4c4c1c53 P 3449ca47d21e4736b5badf72ef0f5895 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:28.203992 31453 tablet_server.cc:196] TabletServer@127.30.183.65:0 shutdown complete.
I20260812 06:18:28.232640 31453 master.cc:562] Master@127.30.183.126:41981 shutting down...
I20260812 06:18:28.237597 31453 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:28.237836 31453 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:28.237937 31453 tablet_replica.cc:333] T 00000000000000000000000000000000 P e0632c299b2b472dbe4ac355fed79491: stopping tablet replica
I20260812 06:18:28.250773 31453 master.cc:584] Master@127.30.183.126:41981 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6803 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:28.346638 31453 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.183.126:42607
I20260812 06:18:28.347060 31453 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:28.350287 31676 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:28.350309 31453 server_base.cc:1061] running on GCE node
W20260812 06:18:28.350317 31673 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:28.350309 31674 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:28.350878 31453 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:28.350927 31453 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:28.350950 31453 hybrid_clock.cc:648] HybridClock initialized: now 1786515508350950 us; error 0 us; skew 500 ppm
I20260812 06:18:28.351820 31453 webserver.cc:533] Webserver started at http://127.30.183.126:42105/ using document root <none> and password file <none>
I20260812 06:18:28.351971 31453 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:28.352062 31453 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:28.352129 31453 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:28.352485 31453 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/master-0-root/instance:
uuid: "2ba2a9db3c8a46d18eb7b510a51e88a9"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-rgb1"
I20260812 06:18:28.354118 31453 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:28.355182 31681 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:28.355605 31453 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:28.355688 31453 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/master-0-root
uuid: "2ba2a9db3c8a46d18eb7b510a51e88a9"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-rgb1"
I20260812 06:18:28.355793 31453 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:28.366804 31453 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:28.367300 31453 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:28.373598 31453 rpc_server.cc:307] RPC server started. Bound to: 127.30.183.126:42607
I20260812 06:18:28.377887 31741 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:28.378072 31740 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.183.126:42607 every 8 connection(s)
I20260812 06:18:28.391671 31741 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9: Bootstrap starting.
I20260812 06:18:28.392818 31741 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:28.394186 31741 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9: No bootstrap required, opened a new log
I20260812 06:18:28.394693 31741 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ba2a9db3c8a46d18eb7b510a51e88a9" member_type: VOTER }
I20260812 06:18:28.394815 31741 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:28.394865 31741 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2ba2a9db3c8a46d18eb7b510a51e88a9, State: Initialized, Role: FOLLOWER
I20260812 06:18:28.395043 31741 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [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: "2ba2a9db3c8a46d18eb7b510a51e88a9" member_type: VOTER }
I20260812 06:18:28.395141 31741 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:28.395183 31741 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:28.395238 31741 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:28.396373 31741 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ba2a9db3c8a46d18eb7b510a51e88a9" member_type: VOTER }
I20260812 06:18:28.396559 31741 leader_election.cc:304] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [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: 2ba2a9db3c8a46d18eb7b510a51e88a9; no voters: 
I20260812 06:18:28.396850 31741 leader_election.cc:290] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:28.397101 31744 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:28.397356 31744 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [term 1 LEADER]: Becoming Leader. State: Replica: 2ba2a9db3c8a46d18eb7b510a51e88a9, State: Running, Role: LEADER
I20260812 06:18:28.397375 31741 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:28.397513 31744 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [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: "2ba2a9db3c8a46d18eb7b510a51e88a9" member_type: VOTER }
I20260812 06:18:28.398003 31745 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2ba2a9db3c8a46d18eb7b510a51e88a9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ba2a9db3c8a46d18eb7b510a51e88a9" member_type: VOTER } }
I20260812 06:18:28.398026 31746 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2ba2a9db3c8a46d18eb7b510a51e88a9. Latest consensus state: current_term: 1 leader_uuid: "2ba2a9db3c8a46d18eb7b510a51e88a9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2ba2a9db3c8a46d18eb7b510a51e88a9" member_type: VOTER } }
I20260812 06:18:28.398200 31745 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:28.398206 31746 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:28.398800 31752 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:28.399501 31752 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:28.399855 31453 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:28.401501 31752 catalog_manager.cc:1383] Generated new cluster ID: 967f6c9e9d0e4d27960321ba53042214
I20260812 06:18:28.401562 31752 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:28.416610 31752 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:28.417212 31752 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:28.422667 31752 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9: Generated new TSK 0
I20260812 06:18:28.422897 31752 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:28.432688 31453 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:28.435245 31765 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:28.435345 31453 server_base.cc:1061] running on GCE node
W20260812 06:18:28.435477 31764 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:28.435559 31767 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:28.435767 31453 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:28.435813 31453 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:28.435830 31453 hybrid_clock.cc:648] HybridClock initialized: now 1786515508435831 us; error 0 us; skew 500 ppm
I20260812 06:18:28.436828 31453 webserver.cc:533] Webserver started at http://127.30.183.65:41101/ using document root <none> and password file <none>
I20260812 06:18:28.436987 31453 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:28.437036 31453 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:28.437099 31453 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:28.437486 31453 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/instance:
uuid: "10df04ccb7044f91a4bcc899e5d6bbe7"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-rgb1"
I20260812 06:18:28.439093 31453 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:28.440243 31772 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:28.440623 31453 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:28.440704 31453 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root
uuid: "10df04ccb7044f91a4bcc899e5d6bbe7"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-rgb1"
I20260812 06:18:28.440796 31453 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:28.472491 31453 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:28.473332 31453 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:28.473673 31453 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:28.475521 31453 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:28.475577 31453 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:28.475618 31453 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:28.475670 31453 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:28.480633 31453 rpc_server.cc:307] RPC server started. Bound to: 127.30.183.65:45367
I20260812 06:18:28.480670 31842 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.183.65:45367 every 8 connection(s)
I20260812 06:18:28.491606 31844 heartbeater.cc:344] Connected to a master server at 127.30.183.126:42607
I20260812 06:18:28.491806 31844 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:28.492264 31844 heartbeater.cc:507] Master 127.30.183.126:42607 requested a full tablet report, sending...
I20260812 06:18:28.493296 31698 ts_manager.cc:194] Registered new tserver with Master: 10df04ccb7044f91a4bcc899e5d6bbe7 (127.30.183.65:45367)
I20260812 06:18:28.493582 31453 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012460586s
I20260812 06:18:28.494228 31698 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42690
I20260812 06:18:28.503095 31698 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42698:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:28.513492 31803 tablet_service.cc:1511] Processing CreateTablet for tablet 431d3df9c38c429a8365870aaec9a887 (DEFAULT_TABLE table=heavy-update-compaction-test [id=bb76cbf41ac14c64a57113e869bad07e]), partition=
I20260812 06:18:28.513991 31803 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 431d3df9c38c429a8365870aaec9a887. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:28.516225 31857 tablet_bootstrap.cc:492] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Bootstrap starting.
I20260812 06:18:28.517483 31857 tablet_bootstrap.cc:654] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:28.518714 31857 tablet_bootstrap.cc:492] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: No bootstrap required, opened a new log
I20260812 06:18:28.518800 31857 ts_tablet_manager.cc:1403] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:18:28.519196 31857 raft_consensus.cc:359] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "10df04ccb7044f91a4bcc899e5d6bbe7" member_type: VOTER last_known_addr { host: "127.30.183.65" port: 45367 } }
I20260812 06:18:28.519292 31857 raft_consensus.cc:385] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:28.519316 31857 raft_consensus.cc:740] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 10df04ccb7044f91a4bcc899e5d6bbe7, State: Initialized, Role: FOLLOWER
I20260812 06:18:28.519476 31857 consensus_queue.cc:260] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [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: "10df04ccb7044f91a4bcc899e5d6bbe7" member_type: VOTER last_known_addr { host: "127.30.183.65" port: 45367 } }
I20260812 06:18:28.519577 31857 raft_consensus.cc:399] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:28.519608 31857 raft_consensus.cc:493] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:28.519639 31857 raft_consensus.cc:3060] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:28.520678 31857 raft_consensus.cc:515] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "10df04ccb7044f91a4bcc899e5d6bbe7" member_type: VOTER last_known_addr { host: "127.30.183.65" port: 45367 } }
I20260812 06:18:28.520831 31857 leader_election.cc:304] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [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: 10df04ccb7044f91a4bcc899e5d6bbe7; no voters: 
I20260812 06:18:28.521055 31857 leader_election.cc:290] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:28.521167 31859 raft_consensus.cc:2804] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:28.521482 31857 ts_tablet_manager.cc:1434] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:28.521507 31844 heartbeater.cc:499] Master 127.30.183.126:42607 was elected leader, sending a full tablet report...
I20260812 06:18:28.521514 31859 raft_consensus.cc:697] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [term 1 LEADER]: Becoming Leader. State: Replica: 10df04ccb7044f91a4bcc899e5d6bbe7, State: Running, Role: LEADER
I20260812 06:18:28.521749 31859 consensus_queue.cc:237] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [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: "10df04ccb7044f91a4bcc899e5d6bbe7" member_type: VOTER last_known_addr { host: "127.30.183.65" port: 45367 } }
I20260812 06:18:28.523247 31698 catalog_manager.cc:5719] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 10df04ccb7044f91a4bcc899e5d6bbe7 (127.30.183.65). New cstate: current_term: 1 leader_uuid: "10df04ccb7044f91a4bcc899e5d6bbe7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "10df04ccb7044f91a4bcc899e5d6bbe7" member_type: VOTER last_known_addr { host: "127.30.183.65" port: 45367 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:28.590269 31453 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.016s	sys 0.009s
I20260812 06:18:28.731725 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushMRSOp(431d3df9c38c429a8365870aaec9a887): perf score=15.086190
I20260812 06:18:28.882197 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushMRSOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.150s	user 0.108s	sys 0.039s Metrics: {"bytes_written":11897249,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":192,"dirs.run_wall_time_us":886,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40919,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1450}
I20260812 06:18:28.882998 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling LogGCOp(431d3df9c38c429a8365870aaec9a887): free 20743880 bytes of WAL
I20260812 06:18:28.883281 31777 log_reader.cc:385] T 431d3df9c38c429a8365870aaec9a887: removed 2 log segments from log reader
I20260812 06:18:28.883359 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000001 (ops 1-6)
I20260812 06:18:28.883417 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000002 (ops 7-11)
I20260812 06:18:28.887573 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: LogGCOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:28.888015 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:28.903153 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5519,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.903647 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:29.053578 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.150s	user 0.106s	sys 0.044s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":779,"lbm_read_time_us":9879,"lbm_reads_lt_1ms":458,"lbm_write_time_us":29453,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":392,"threads_started":5,"update_count":1950}
I20260812 06:18:29.054383 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling UndoDeltaBlockGCOp(431d3df9c38c429a8365870aaec9a887): 12719217 bytes on disk
I20260812 06:18:29.054864 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: UndoDeltaBlockGCOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:18:29.055343 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:29.101241 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.046s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16704,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.101769 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:29.116195 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5491,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.116756 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:29.254806 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.138s	user 0.104s	sys 0.033s 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":908,"lbm_read_time_us":9907,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26501,"lbm_writes_lt_1ms":443,"mutex_wait_us":369,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:18:29.255506 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:29.313364 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.058s	user 0.038s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18270,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.314213 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:29.326972 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.327486 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:29.519681 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.192s	user 0.120s	sys 0.068s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":407,"lbm_read_time_us":11896,"lbm_reads_lt_1ms":472,"lbm_write_time_us":33290,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:29.520423 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:29.565196 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.045s	user 0.037s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18606,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.565754 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:29.687537 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.122s	user 0.098s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":140,"lbm_read_time_us":8002,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22616,"lbm_writes_lt_1ms":343,"mutex_wait_us":38,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":1500}
I20260812 06:18:29.688654 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:29.740998 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.052s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17721,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.741554 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:29.754765 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4642,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.755466 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:29.893249 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.138s	user 0.106s	sys 0.031s 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":585,"lbm_read_time_us":8059,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26740,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:18:29.893816 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:29.950495 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.057s	user 0.030s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16451,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.951236 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:29.964808 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5318,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.965337 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:30.145216 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.180s	user 0.102s	sys 0.077s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":568,"lbm_read_time_us":12283,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27090,"lbm_writes_lt_1ms":443,"mutex_wait_us":220,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":53120,"update_count":2000}
I20260812 06:18:30.146008 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:30.189836 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.044s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16937,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.190497 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:30.203959 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5149,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.204777 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:30.355611 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.151s	user 0.122s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":12001,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26564,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:18:30.356173 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:30.412546 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.056s	user 0.010s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18293,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.413249 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:30.425449 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.426306 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushMRSOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:30.458346 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushMRSOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.032s	user 0.028s	sys 0.002s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1690,"drs_written":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1625,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:30.459098 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling LogGCOp(431d3df9c38c429a8365870aaec9a887): free 124257246 bytes of WAL
I20260812 06:18:30.459313 31777 log_reader.cc:385] T 431d3df9c38c429a8365870aaec9a887: removed 12 log segments from log reader
I20260812 06:18:30.459379 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000003 (ops 12-16)
I20260812 06:18:30.459421 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000004 (ops 17-20)
I20260812 06:18:30.459450 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000005 (ops 21-25)
I20260812 06:18:30.459472 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000006 (ops 26-30)
I20260812 06:18:30.459494 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000007 (ops 31-35)
I20260812 06:18:30.459527 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000008 (ops 36-40)
I20260812 06:18:30.459553 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000009 (ops 41-45)
I20260812 06:18:30.459576 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000010 (ops 46-50)
I20260812 06:18:30.459599 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000011 (ops 51-55)
I20260812 06:18:30.459625 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000012 (ops 56-60)
I20260812 06:18:30.459652 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000013 (ops 61-65)
I20260812 06:18:30.459676 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000014 (ops 66-70)
I20260812 06:18:30.491367 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: LogGCOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:30.491853 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling UndoDeltaBlockGCOp(431d3df9c38c429a8365870aaec9a887): 473 bytes on disk
I20260812 06:18:30.492303 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: UndoDeltaBlockGCOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:30.492830 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:30.521258 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.028s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.521781 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:30.534475 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4928,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.535072 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:30.723879 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.189s	user 0.152s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1315,"lbm_read_time_us":11972,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39136,"lbm_writes_lt_1ms":643,"mutex_wait_us":330,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20992,"thread_start_us":98,"threads_started":1,"update_count":3000}
I20260812 06:18:30.724637 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=14.095187
I20260812 06:18:30.776028 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.051s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19986,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.776634 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:30.787573 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.788160 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:30.940600 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.152s	user 0.128s	sys 0.024s 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":418,"lbm_read_time_us":10731,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28034,"lbm_writes_lt_1ms":543,"mutex_wait_us":95,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:18:30.941325 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:30.976943 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.035s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15548,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.977543 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:31.105086 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.127s	user 0.093s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":6219,"lbm_read_time_us":7397,"lbm_reads_lt_1ms":367,"lbm_write_time_us":19424,"lbm_writes_lt_1ms":343,"mutex_wait_us":1869,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":1500}
I20260812 06:18:31.105965 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:31.153750 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.048s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16586,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.154398 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:31.165844 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4324,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.166625 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:31.298822 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.132s	user 0.096s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":475,"lbm_read_time_us":7643,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26547,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":2000}
I20260812 06:18:31.299343 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:31.341356 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.042s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16319,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.341969 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:31.354797 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4683,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.355476 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:31.488890 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.133s	user 0.105s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":748,"lbm_read_time_us":8444,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27262,"lbm_writes_lt_1ms":443,"mutex_wait_us":331,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2000}
I20260812 06:18:31.489727 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:31.546648 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.057s	user 0.020s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16014,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.547283 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:31.559705 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5039,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.560272 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:31.715864 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.155s	user 0.106s	sys 0.048s 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":857,"lbm_read_time_us":11685,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26340,"lbm_writes_lt_1ms":443,"mutex_wait_us":99,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:31.716727 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:31.767323 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.050s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16062,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.767876 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:31.779883 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4483,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.780618 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:31.924124 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.143s	user 0.122s	sys 0.021s 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":568,"lbm_read_time_us":9633,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28077,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2000}
I20260812 06:18:31.925253 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:31.966534 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.041s	user 0.028s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19070,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.967067 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:31.980507 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.981047 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushMRSOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:32.014240 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushMRSOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.033s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":362,"dirs.run_wall_time_us":1758,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2024,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:32.015131 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling LogGCOp(431d3df9c38c429a8365870aaec9a887): free 117302573 bytes of WAL
I20260812 06:18:32.015457 31777 log_reader.cc:385] T 431d3df9c38c429a8365870aaec9a887: removed 12 log segments from log reader
I20260812 06:18:32.015513 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000015 (ops 71-75)
I20260812 06:18:32.015573 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000016 (ops 76-80)
I20260812 06:18:32.015626 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000017 (ops 81-84)
I20260812 06:18:32.015702 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000018 (ops 85-89)
I20260812 06:18:32.015774 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000019 (ops 90-94)
I20260812 06:18:32.015826 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000020 (ops 95-98)
I20260812 06:18:32.015872 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000021 (ops 99-103)
I20260812 06:18:32.015929 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000022 (ops 104-108)
I20260812 06:18:32.015969 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000023 (ops 109-113)
I20260812 06:18:32.016013 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000024 (ops 114-118)
I20260812 06:18:32.016060 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000025 (ops 119-123)
I20260812 06:18:32.016104 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000026 (ops 124-128)
I20260812 06:18:32.040126 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: LogGCOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:32.040904 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=3.181125
I20260812 06:18:32.053498 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4666,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:32.054034 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:32.068248 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5127,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.068922 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling UndoDeltaBlockGCOp(431d3df9c38c429a8365870aaec9a887): 472 bytes on disk
I20260812 06:18:32.069391 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: UndoDeltaBlockGCOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.070014 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:32.248952 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.179s	user 0.141s	sys 0.036s 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":1616,"lbm_read_time_us":12295,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36236,"lbm_writes_lt_1ms":643,"mutex_wait_us":894,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":110,"threads_started":1,"update_count":3000}
I20260812 06:18:32.249759 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=14.095187
I20260812 06:18:32.309687 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.060s	user 0.022s	sys 0.037s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26508,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.310410 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:32.323364 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5118,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.323849 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:32.497928 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.174s	user 0.128s	sys 0.033s 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":200,"lbm_read_time_us":10215,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34085,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":34688,"update_count":2500}
I20260812 06:18:32.498836 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=14.095187
I20260812 06:18:32.556862 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.058s	user 0.023s	sys 0.031s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":26374,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.557799 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:32.588891 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.031s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6044,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.589399 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:32.600286 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.600775 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:32.788345 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.187s	user 0.148s	sys 0.038s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877223,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":249,"lbm_read_time_us":13852,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38372,"lbm_writes_lt_1ms":643,"mutex_wait_us":53,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":34560,"update_count":3000}
I20260812 06:18:32.789050 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=14.095187
I20260812 06:18:32.848446 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.059s	user 0.014s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23501,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.849119 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:32.862919 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.863461 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:33.036386 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.173s	user 0.126s	sys 0.044s 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":128,"lbm_read_time_us":14346,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32237,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":40832,"update_count":2500}
I20260812 06:18:33.037020 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=11.118625
I20260812 06:18:33.075680 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.038s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16495,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:33.076619 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:33.090914 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5621,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.091424 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:33.219110 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.128s	user 0.106s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":438,"lbm_read_time_us":7578,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26581,"lbm_writes_lt_1ms":443,"mutex_wait_us":81,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2000}
I20260812 06:18:33.219828 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:33.269753 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.050s	user 0.024s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19204,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.270618 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:33.282222 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4357,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.283071 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:33.417995 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.135s	user 0.119s	sys 0.015s 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":388,"lbm_read_time_us":9194,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26595,"lbm_writes_lt_1ms":443,"mutex_wait_us":78,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:33.418977 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=10.126437
I20260812 06:18:33.481043 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.062s	user 0.034s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19043,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.481806 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:33.496086 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6432,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.496785 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushMRSOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:33.543546 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushMRSOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.047s	user 0.039s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":290,"dirs.run_wall_time_us":2505,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1820,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:33.544378 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling LogGCOp(431d3df9c38c429a8365870aaec9a887): free 127961371 bytes of WAL
I20260812 06:18:33.544699 31777 log_reader.cc:385] T 431d3df9c38c429a8365870aaec9a887: removed 12 log segments from log reader
I20260812 06:18:33.544752 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000027 (ops 129-133)
I20260812 06:18:33.544787 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000028 (ops 134-138)
I20260812 06:18:33.544826 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000029 (ops 139-143)
I20260812 06:18:33.544898 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000030 (ops 144-148)
I20260812 06:18:33.544937 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000031 (ops 149-153)
I20260812 06:18:33.545004 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000032 (ops 154-158)
I20260812 06:18:33.545051 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000033 (ops 159-163)
I20260812 06:18:33.545118 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000034 (ops 164-168)
I20260812 06:18:33.545169 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000035 (ops 169-173)
I20260812 06:18:33.545213 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000036 (ops 174-178)
I20260812 06:18:33.545261 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000037 (ops 179-183)
I20260812 06:18:33.545313 31777 log.cc:1079] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: Deleting log segment in path: /tmp/dist-test-taskL8i2Jr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515501531379-31453-0/minicluster-data/ts-0-root/wals/431d3df9c38c429a8365870aaec9a887/wal-000000038 (ops 184-188)
I20260812 06:18:33.572382 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: LogGCOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.028s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:33.573037 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling UndoDeltaBlockGCOp(431d3df9c38c429a8365870aaec9a887): 473 bytes on disk
I20260812 06:18:33.573654 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: UndoDeltaBlockGCOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.574244 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=3.181125
I20260812 06:18:33.601703 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.027s	user 0.018s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7783,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:33.602193 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=2.188937
I20260812 06:18:33.612958 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3869,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.613546 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:33.812323 31453 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.222s	user 1.947s	sys 0.185s
I20260812 06:18:33.832739 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.218s	user 0.155s	sys 0.063s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14582,"lbm_reads_lt_1ms":670,"lbm_write_time_us":37915,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":3000}
I20260812 06:18:33.833372 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887): perf score=14.095187
I20260812 06:18:33.872290 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: FlushDeltaMemStoresOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.039s	user 0.029s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19102,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.872852 31845 maintenance_manager.cc:419] P 10df04ccb7044f91a4bcc899e5d6bbe7: Scheduling MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887): perf score=1.000000
I20260812 06:18:33.937879 31453 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.125s	user 0.000s	sys 0.002s
I20260812 06:18:33.938555 31453 tablet_server.cc:179] TabletServer@127.30.183.65:0 shutting down...
I20260812 06:18:34.027159 31777 maintenance_manager.cc:643] P 10df04ccb7044f91a4bcc899e5d6bbe7: MajorDeltaCompactionOp(431d3df9c38c429a8365870aaec9a887) complete. Timing: real 0.154s	user 0.108s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":715,"lbm_read_time_us":12826,"lbm_reads_lt_1ms":467,"lbm_write_time_us":31038,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":363,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:18:34.028687 31453 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:34.028932 31453 tablet_replica.cc:333] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7: stopping tablet replica
I20260812 06:18:34.029155 31453 raft_consensus.cc:2243] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:34.029361 31453 raft_consensus.cc:2272] T 431d3df9c38c429a8365870aaec9a887 P 10df04ccb7044f91a4bcc899e5d6bbe7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:34.044973 31453 tablet_server.cc:196] TabletServer@127.30.183.65:0 shutdown complete.
I20260812 06:18:34.066721 31453 master.cc:562] Master@127.30.183.126:42607 shutting down...
I20260812 06:18:34.070452 31453 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:34.070670 31453 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:34.070756 31453 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2ba2a9db3c8a46d18eb7b510a51e88a9: stopping tablet replica
I20260812 06:18:34.083875 31453 master.cc:584] Master@127.30.183.126:42607 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5827 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12631 ms total)

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