Scavenging 22 chunks files took 10 hours

EventStoreDB
1

Hi,

I’ve noticed that the scavenge process is taking too long. I ran a test with 22 chunk files (around 6GB) that were backed up from our production environment and restored for testing purposes, and it took 10 hours to complete.

I ran the scavenge with 4 threads and 100 throttlePercent.

In the test environment, I’ve configured an ESDB cluster on AKS with 3 nodes and 1 readonly replica. Each node has been allocated with sufficient resources, even more than what’s allocated in our production environment.

resources:
  limits:
    cpu: 3000m
    memory: 12Gi

  requests:
    cpu: 1500m
    memory: 8Gi

We also use Azure Premium Files. Each node has own storage, and the capacity of the storage on each node is:
5Ti
Maximum IO/s: 8120
Burst IO/s : 15360
Throughput rate 613.0 MiB/s

There are two persistent subscriptions which are configured like the below.

  "config": {
    "resolveLinktos": true,
    "startFrom": 0,
    "startPosition": "C:0/P:0",
    "messageTimeoutMilliseconds": 30000,
    "extraStatistics": false,
    "maxRetryCount": 3,
    "liveBufferSize": 500,
    "bufferSize": 500,
    "readBatchSize": 20,
    "preferRoundRobin": true,
    "checkPointAfterMilliseconds": 2000,
    "minCheckPointCount": 1,
    "maxCheckPointCount": 1000,
    "maxSubscriberCount": 0,
    "namedConsumerStrategy": "RoundRobin"
  },

And this is the node configuration info.

2024-03-11 02:25:04.457 "ES VERSION:"             "23.10.0.0" ("oss-v23.10.0"/"8660912b8", "2023-10-24T16:13:49+01:00")
2024-03-11 02:25:04.479 [    1, 1,02:25:04.457,INF] "RUNTIME:"                ".NET 6.0.23/e0f0de876" (64-bit)
2024-03-11 02:25:04.479 [    1, 1,02:25:04.455,INF] "OS:"                     Linux ("Unix 5.15.0.1041")
2024-03-11 02:25:04.479 [    1, 1,02:25:04.445,INF] "OS ARCHITECTURE:"        X64
2024-03-11 02:25:04.480 [    1, 1,02:25:04.457,INF] "LOGS:"                   "/var/log/eventstore"
2024-03-11 02:25:04.480 [    1, 1,02:25:04.457,INF] "GC:"                     "3 GENERATIONS" "IsServerGC: False" "Latency Mode: Interactive"
2024-03-11 02:25:04.480          SCAVENGE BACKEND CACHE SIZE:                   2147483648 (Environment Variables)
2024-03-11 02:25:04.480          MAX TRUNCATION:                                -1 (Environment Variables)
2024-03-11 02:25:04.480     DATABASE OPTIONS:
2024-03-11 02:25:04.480          QUORUM SIZE:                                   2 (Environment Variables)
2024-03-11 02:25:04.480          NODE PRIORITY:                                 0 (Environment Variables)
2024-03-11 02:25:04.480          LEADER ELECTION TIMEOUT MS:                    20000 (Environment Variables)
2024-03-11 02:25:04.480          EXT TCP HEARTBEAT INTERVAL:                    2000 (<DEFAULT>)
2024-03-11 02:25:04.480          EXT HOST ADVERTISE AS:                          (<DEFAULT>)
2024-03-11 02:25:04.480          ENABLE UNIX SOCKET:                            False (<DEFAULT>)
2024-03-11 02:25:04.480          CONNECTION PENDING SEND BYTES THRESHOLD:       10485760 (<DEFAULT>)
2024-03-11 02:25:04.480          DISABLE STATS ON HTTP:                         False (<DEFAULT>)
2024-03-11 02:25:04.480     DEV MODE OPTIONS:
2024-03-11 02:25:04.480          DEV:                                           False (<DEFAULT>)
2024-03-11 02:25:04.480          REMOVE DEV CERTS:                              False (<DEFAULT>)
2024-03-11 02:25:04.480     GRPC OPTIONS:
2024-03-11 02:25:04.480          KEEP ALIVE INTERVAL:                           10000 (<DEFAULT>)
2024-03-11 02:25:04.480          KEEP ALIVE TIMEOUT:                            10000 (<DEFAULT>)
2024-03-11 02:25:04.480     INTERFACE OPTIONS:
2024-03-11 02:25:04.480          ENABLE TRUSTED AUTH:                           False (<DEFAULT>)
2024-03-11 02:25:04.480          ADVERTISE HTTP PORT TO CLIENT AS:              0 (<DEFAULT>)
2024-03-11 02:25:04.480          DEFAULT OPS PASSWORD:                          ******** (<DEFAULT>)
2024-03-11 02:25:04.480          ADVERTISE NODE PORT TO CLIENT AS:              0 (<DEFAULT>)
2024-03-11 02:25:04.480          ADVERTISE TCP PORT TO CLIENT AS:               0 (<DEFAULT>)
2024-03-11 02:25:04.480          CONNECTION QUEUE SIZE THRESHOLD:               50000 (<DEFAULT>)
2024-03-11 02:25:04.480          DISABLE EXTERNAL TCP TLS:                      False (<DEFAULT>)
2024-03-11 02:25:04.480          DISABLE GOSSIP ON HTTP:                        False (<DEFAULT>)
2024-03-11 02:25:04.480          DISABLE INTERNAL TCP TLS:                      False (<DEFAULT>)
2024-03-11 02:25:04.480          GOSSIP TIMEOUT MS:                             5000 (Environment Variables)
2024-03-11 02:25:04.480          GOSSIP SEED:                                   <Node1 External Ingress>:2115,<Node2 External Ingress>:2115,<Readonly Replica External Ingress>:2115 (Environment Variables)
2024-03-11 02:25:04.480          GOSSIP ON SINGLE NODE:                          (<DEFAULT>)
2024-03-11 02:25:04.480          CLUSTER SIZE:                                  3 (Environment Variables)
2024-03-11 02:25:04.480          NODE TCP PORT ADVERTISE AS:                    0 (<DEFAULT>)
2024-03-11 02:25:04.480          REPLICATION TCP PORT ADVERTISE AS:             0 (<DEFAULT>)
2024-03-11 02:25:04.480     LOGGING OPTIONS:
2024-03-11 02:25:04.480          DISABLE LOG FILE:                              False (<DEFAULT>)
2024-03-11 02:25:04.480          LOG:                                           /var/log/eventstore (<DEFAULT>)
2024-03-11 02:25:04.480          LOG CONFIG:                                    logconfig.json (<DEFAULT>)
2024-03-11 02:25:04.480          LOG CONSOLE FORMAT:                            Plain (<DEFAULT>)
2024-03-11 02:25:04.480          NODE PORT ADVERTISE AS:                        0 (<DEFAULT>)
2024-03-11 02:25:04.480     CERTIFICATE OPTIONS:
2024-03-11 02:25:04.480          ALLOW ANONYMOUS ENDPOINT ACCESS:               true (Environment Variables)
2024-03-11 02:25:04.480     APPLICATION OPTIONS:
2024-03-11 02:25:04.480 MODIFIED OPTIONS:
2024-03-11 02:25:04.480          SCAVENGE BACKEND PAGE SIZE:                    32768 (Environment Variables)
2024-03-11 02:25:04.480          INSECURE:                                      false (Environment Variables)
2024-03-11 02:25:04.480          DISCOVER VIA DNS:                              false (Environment Variables)
2024-03-11 02:25:04.480          NODE HEARTBEAT TIMEOUT:                        1000 (<DEFAULT>)
2024-03-11 02:25:04.480          INT TCP PORT ADVERTISE AS:                     0 (<DEFAULT>)
2024-03-11 02:25:04.480          CLUSTER GOSSIP PORT:                           2115 (Environment Variables)
2024-03-11 02:25:04.480     CLUSTER OPTIONS:
2024-03-11 02:25:04.480          CERTIFICATE PRIVATE KEY FILE:                  /opt/eventstore/certs/dev/node3/node3.key (Environment Variables)
2024-03-11 02:25:04.480          CERTIFICATE FILE:                              /opt/eventstore/certs/dev/node3/node3.crt (Environment Variables)
2024-03-11 02:25:04.480     CERTIFICATE OPTIONS (FROM FILE):
2024-03-11 02:25:04.480          TRUSTED ROOT CERTIFICATES PATH:                /opt/eventstore/certs/dev/ca (Environment Variables)
2024-03-11 02:25:04.480          EXT TCP HEARTBEAT TIMEOUT:                     1000 (<DEFAULT>)
2024-03-11 02:25:04.480          NODE HEARTBEAT INTERVAL:                       2000 (<DEFAULT>)
2024-03-11 02:25:04.480          EXT TCP PORT:                                  1113 (<DEFAULT>)
2024-03-11 02:25:04.480          DEFAULT ADMIN PASSWORD:                        ******** (<DEFAULT>)
2024-03-11 02:25:04.480          HTTP PORT:                                     2113 (<DEFAULT>)
2024-03-11 02:25:04.480          HTTP PORT ADVERTISE AS:                        0 (<DEFAULT>)
2024-03-11 02:25:04.480          INT HOST ADVERTISE AS:                          (<DEFAULT>)
2024-03-11 02:25:04.480          INT TCP HEARTBEAT INTERVAL:                    700 (<DEFAULT>)
2024-03-11 02:25:04.480          INT TCP HEARTBEAT TIMEOUT:                     700 (<DEFAULT>)
2024-03-11 02:25:04.480          INT TCP PORT:                                  1112 (<DEFAULT>)
2024-03-11 02:25:04.480          EXT TCP PORT ADVERTISE AS:                     0 (<DEFAULT>)
2024-03-11 02:25:04.480     DEFAULT USER OPTIONS:
2024-03-11 02:25:04.480          SKIP DB VERIFY:                                false (Environment Variables)
2024-03-11 02:25:04.480          WRITE THROUGH:                                 False (<DEFAULT>)
2024-03-11 02:25:04.480          LOG FAILED AUTHENTICATION ATTEMPTS:            False (<DEFAULT>)
2024-03-11 02:25:04.480          LOG HTTP REQUESTS:                             False (<DEFAULT>)
2024-03-11 02:25:04.480          MAX APPEND SIZE:                               1048576 (<DEFAULT>)
2024-03-11 02:25:04.480          WRITE TIMEOUT MS:                              2000 (<DEFAULT>)
2024-03-11 02:25:04.480          OVERRIDE ANONYMOUS ENDPOINT ACCESS FOR GOSSIP: True (<DEFAULT>)
2024-03-11 02:25:04.480          SKIP INDEX SCAN ON READS:                      False (<DEFAULT>)
2024-03-11 02:25:04.480          STATS PERIOD SEC:                              30 (<DEFAULT>)
2024-03-11 02:25:04.480          TELEMETRY OPTOUT:                              False (<DEFAULT>)
2024-03-11 02:25:04.480          ADVERTISE HOST TO CLIENT AS:                   <Node 3 External Ingress> (Environment Variables)
2024-03-11 02:25:04.480          WHAT IF:                                       False (<DEFAULT>)
2024-03-11 02:25:04.480          WORKER THREADS:                                0 (<DEFAULT>)
2024-03-11 02:25:04.480     AUTHENTICATION/AUTHORIZATION OPTIONS:
2024-03-11 02:25:04.480          AUTHENTICATION CONFIG:                          (<DEFAULT>)
2024-03-11 02:25:04.480          AUTHENTICATION TYPE:                           internal (<DEFAULT>)
2024-03-11 02:25:04.480          AUTHORIZATION CONFIG:                           (<DEFAULT>)
2024-03-11 02:25:04.480          AUTHORIZATION TYPE:                            internal (<DEFAULT>)
2024-03-11 02:25:04.480          DISABLE FIRST LEVEL HTTP AUTHORIZATION:        False (<DEFAULT>)
2024-03-11 02:25:04.480     CERTIFICATE OPTIONS:
2024-03-11 02:25:04.480          CERTIFICATE RESERVED NODE COMMON NAME:          (<DEFAULT>)
2024-03-11 02:25:04.480     CERTIFICATE OPTIONS (FROM FILE):
2024-03-11 02:25:04.480          CERTIFICATE PASSWORD:                          ******** (<DEFAULT>)
2024-03-11 02:25:04.480          HELP:                                          False (<DEFAULT>)
2024-03-11 02:25:04.480          ENABLE HISTOGRAMS:                             False (<DEFAULT>)
2024-03-11 02:25:04.480          DISABLE HTTP CACHING:                          False (<DEFAULT>)
2024-03-11 02:25:04.480          CONFIG:                                        /etc/eventstore/eventstore.conf (<DEFAULT>)
2024-03-11 02:25:04.480          DISABLE ADMIN UI:                              false (Environment Variables)
2024-03-11 02:25:04.480          ENABLE ATOM PUB OVER HTTP:                     true (Environment Variables)
2024-03-11 02:25:04.480          ENABLE EXTERNAL TCP:                           true (Environment Variables)
2024-03-11 02:25:04.480          EXT IP:                                        0.0.0.0 (Yaml)
2024-03-11 02:25:04.480          INT IP:                                        0.0.0.0 (Yaml)
2024-03-11 02:25:04.480          NODE HOST ADVERTISE AS:                        <Node 3 External Ingress> (Environment Variables)
2024-03-11 02:25:04.480          NODE IP:                                       <Node IP Address> (Environment Variables)
2024-03-11 02:25:04.480          NODE PORT:                                     2115 (Environment Variables)
2024-03-11 02:25:04.480          NODE TCP PORT:                                 1112 (Environment Variables)
2024-03-11 02:25:04.480          REPLICATION HEARTBEAT INTERVAL:                5000 (Environment Variables)
2024-03-11 02:25:04.480          CERTIFICATE PRIVATE KEY PASSWORD:              ******** (<DEFAULT>)
2024-03-11 02:25:04.480          REPLICATION HEARTBEAT TIMEOUT:                 3000 (Environment Variables)
2024-03-11 02:25:04.480          REPLICATION IP:                                <Readonly Replica IP Address> (Environment Variables)
2024-03-11 02:25:04.480          REPLICATION PORT:                              1115 (Environment Variables)
2024-03-11 02:25:04.480     LOGGING OPTIONS:
2024-03-11 02:25:04.480          LOG LEVEL:                                     Verbose (Environment Variables)
2024-03-11 02:25:04.480     PROJECTION OPTIONS:
2024-03-11 02:25:04.480          RUN PROJECTIONS:                               All (Environment Variables)
2024-03-11 02:25:04.480 DEFAULT OPTIONS:
2024-03-11 02:25:04.480     APPLICATION OPTIONS:
2024-03-11 02:25:04.480          ALLOW ANONYMOUS STREAM ACCESS:                 False (<DEFAULT>)
2024-03-11 02:25:04.480          ALLOW UNKNOWN OPTIONS:                         False (<DEFAULT>)
2024-03-11 02:25:04.480          REPLICATION HOST ADVERTISE AS:                 <Node 3 External Ingress> (Environment Variables)
2024-03-11 02:25:04.480     CERTIFICATE OPTIONS (FROM STORE):
2024-03-11 02:25:04.480          VERSION:                                       False (<DEFAULT>)
2024-03-11 02:25:04.480          CERTIFICATE STORE NAME:                         (<DEFAULT>)
2024-03-11 02:25:04.480          CHUNK INITIAL READER COUNT:                    5 (<DEFAULT>)
2024-03-11 02:25:04.480          CHUNK SIZE:                                    268435456 (<DEFAULT>)
2024-03-11 02:25:04.480          CHUNKS CACHE SIZE:                             536871424 (<DEFAULT>)
2024-03-11 02:25:04.480          COMMIT TIMEOUT MS:                             2000 (<DEFAULT>)
2024-03-11 02:25:04.480          DB:                                            /var/lib/eventstore (<DEFAULT>)
2024-03-11 02:25:04.480          DB LOG FORMAT:                                 V2 (<DEFAULT>)
2024-03-11 02:25:04.480          DISABLE SCAVENGE MERGING:                      False (<DEFAULT>)
2024-03-11 02:25:04.480          HASH COLLISION READ LIMIT:                     100 (<DEFAULT>)
2024-03-11 02:25:04.480          INDEX:                                          (<DEFAULT>)
2024-03-11 02:25:04.480          INDEX CACHE DEPTH:                             16 (<DEFAULT>)
2024-03-11 02:25:04.480          INDEX CACHE SIZE:                              0 (<DEFAULT>)
2024-03-11 02:25:04.480          INITIALIZATION THREADS:                        1 (<DEFAULT>)
2024-03-11 02:25:04.480          MAX AUTO MERGE INDEX LEVEL:                    2147483647 (<DEFAULT>)
2024-03-11 02:25:04.480          MAX MEM TABLE SIZE:                            1000000 (<DEFAULT>)
2024-03-11 02:25:04.480          CACHED CHUNKS:                                 -1 (<DEFAULT>)
2024-03-11 02:25:04.480          MEM DB:                                        False (<DEFAULT>)
2024-03-11 02:25:04.480          OPTIMIZE INDEX MERGE:                          False (<DEFAULT>)
2024-03-11 02:25:04.480          PREPARE TIMEOUT MS:                            2000 (<DEFAULT>)
2024-03-11 02:25:04.480          READER THREADS COUNT:                          0 (<DEFAULT>)
2024-03-11 02:25:04.480          REDUCE FILE CACHE PRESSURE:                    False (<DEFAULT>)
2024-03-11 02:25:04.480          SCAVENGE HASH USERS CACHE CAPACITY:            100000 (<DEFAULT>)
2024-03-11 02:25:04.480          SCAVENGE HISTORY MAX AGE:                      30 (<DEFAULT>)
2024-03-11 02:25:04.480          SKIP INDEX VERIFY:                             False (<DEFAULT>)
2024-03-11 02:25:04.480          STATS STORAGE:                                 File (<DEFAULT>)
2024-03-11 02:25:04.480          STREAM EXISTENCE FILTER SIZE:                  256000000 (<DEFAULT>)
2024-03-11 02:25:04.480          UNBUFFERED:                                    False (<DEFAULT>)
2024-03-11 02:25:04.480          UNSAFE DISABLE FLUSH TO DISK:                  False (<DEFAULT>)
2024-03-11 02:25:04.480          UNSAFE IGNORE HARD DELETE:                     False (<DEFAULT>)
2024-03-11 02:25:04.480          USE INDEX BLOOM FILTERS:                       True (<DEFAULT>)
2024-03-11 02:25:04.480          WRITE STATS TO DB:                             False (<DEFAULT>)
2024-03-11 02:25:04.480          MIN FLUSH DELAY MS:                            2 (<DEFAULT>)
2024-03-11 02:25:04.480          CERTIFICATE STORE LOCATION:                     (<DEFAULT>)
2024-03-11 02:25:04.480     INTERFACE OPTIONS:
2024-03-11 02:25:04.480          GOSSIP INTERVAL MS:                            2000 (<DEFAULT>)
2024-03-11 02:25:04.480          READ ONLY REPLICA:                             False (<DEFAULT>)
2024-03-11 02:25:04.480          ALWAYS KEEP SCAVENGED:                         False (<DEFAULT>)
2024-03-11 02:25:04.480     DATABASE OPTIONS:
2024-03-11 02:25:04.480          UNSAFE ALLOW SURPLUS NODES:                    False (<DEFAULT>)
2024-03-11 02:25:04.480          GOSSIP ALLOWED DIFFERENCE MS:                  60000 (<DEFAULT>)
2024-03-11 02:25:04.480          CLUSTER DNS:                                   fake.dns (<DEFAULT>)
2024-03-11 02:25:04.480     CLUSTER OPTIONS:
2024-03-11 02:25:04.480          DEAD MEMBER REMOVAL PERIOD SEC:                1800 (<DEFAULT>)
2024-03-11 02:25:04.480          TRUSTED ROOT CERTIFICATE SUBJECT NAME:          (<DEFAULT>)
2024-03-11 02:25:04.480          STREAM INFO CACHE CAPACITY:                    0 (<DEFAULT>)
2024-03-11 02:25:04.480          TRUSTED ROOT CERTIFICATE STORE NAME:            (<DEFAULT>)
2024-03-11 02:25:04.480          TRUSTED ROOT CERTIFICATE STORE LOCATION:        (<DEFAULT>)
2024-03-11 02:25:04.480          CERTIFICATE THUMBPRINT:                         (<DEFAULT>)
2024-03-11 02:25:04.480          CERTIFICATE SUBJECT NAME:                       (<DEFAULT>)
2024-03-11 02:25:04.480          TRUSTED ROOT CERTIFICATE THUMBPRINT:            (<DEFAULT>)
2024-03-11 02:25:04.481     PROJECTION OPTIONS:
2024-03-11 02:25:04.481          LOG FILE INTERVAL:                             Day (<DEFAULT>)
2024-03-11 02:25:04.481          LOG FILE RETENTION COUNT:                      31 (<DEFAULT>)
2024-03-11 02:25:04.481          LOG FILE SIZE:                                 1073741824 (<DEFAULT>)
2024-03-11 02:25:04.481          PROJECTION COMPILATION TIMEOUT:                500 (<DEFAULT>)
2024-03-11 02:25:04.481 [    1, 1,02:25:04.480,WRN] DEPRECATED
2024-03-11 02:25:04.481          PROJECTION THREADS:                            3 (<DEFAULT>)
2024-03-11 02:25:04.481          PROJECTIONS QUERY EXPIRY:                      5 (<DEFAULT>)
2024-03-11 02:25:04.481          START STANDARD PROJECTIONS:                    False (<DEFAULT>)
2024-03-11 02:25:04.481          PROJECTION EXECUTION TIMEOUT:                  250 (<DEFAULT>)
2024-03-11 02:25:04.481          FAULT OUT OF ORDER PROJECTIONS:                False (<DEFAULT>)
2024-03-11 02:25:04.518 [    1, 1,02:25:04.518,INF] Cannot find plugins path: "/usr/share/eventstore/plugins"
2024-03-11 02:25:04.661 [    1, 1,02:25:04.661,DBG] MessageHierarchy initialization took 00:00:00.1303244.
2024-03-11 02:25:04.718 [    1, 1,02:25:04.717,INF] The log level was adjusted to: Verbose
2024-03-11 02:25:04.720 [    1, 1,02:25:04.720,INF] Loading the node's certificate(s) from file: "/opt/eventstore/certs/dev/node3/node3.crt"
2024-03-11 02:25:04.953 [    1, 1,02:25:04.953,INF] "CertificateReservedNodeCommonName" auto-configured to: "eventstoredb-node" based on certificate
2024-03-11 02:25:05.085 [    1, 1,02:25:05.085,INF] Quorum size set to 2.
2024-03-11 02:25:05.085 [    1, 1,02:25:05.085,INF] All certificates successfully loaded.
2024-03-11 02:25:05.085 [    1, 1,02:25:05.085,INF] Certificate chain verification successful.
2024-03-11 02:25:05.104 [    1, 1,02:25:05.104,DBG] Using File Checkpoints
2024-03-11 02:25:05.196 [    1, 1,02:25:05.195,INF] ReaderThreadsCount set to 6. Calculated based on processor count of 3 and configured value of 0
2024-03-11 02:25:05.197 [    1, 1,02:25:05.196,INF] WorkerThreads set to 10. Calculated based on a reader thread count of 6 and a configured value of 0

I’m wondering if there’s anything I misconfigured for the scavenge process, or if it’s normal for it to take that long to run?

Additionally, we write a checkpoint every 2 seconds if there is one or more events. Could this be causing the slow scavenge issue?

Your assistance would be greatly appreciated.

2

This is the log for the scavenge.

LOG 1

2024-03-11 04:18:44.708  [    1,57,04:18:44.708,DBG] SCAVENGING: Scavenge Initializing State.
2024-03-11 04:18:44.770  [    1,57,04:18:44.770,DBG] SCAVENGING: Setting page size to 32,768 bytes.
2024-03-11 04:18:45.781  [    1,57,04:18:45.781,DBG] SCAVENGING: ScavengeState size: 0.56 MB. Cache size: 2,147.48 MB. Memory usage: 1.01 MB
2024-03-11 04:18:45.781  [    1,57,04:18:45.781,DBG] SCAVENGING: Scavenge Started.
2024-03-11 04:18:45.798  [    1,57,04:18:45.798,DBG] SCAVENGING: 0 KNOWN COLLISIONS
2024-03-11 04:18:45.827  [    1,57,04:18:45.827,DBG] SCAVENGING: Started a new scavenge with no checkpoint
2024-03-11 04:18:45.829  [    1,57,04:18:45.829,INF] SCAVENGING: Getting latest scavenge point...
2024-03-11 04:18:45.831  [    1,61,04:18:45.831,INF] SCAVENGING: No scavenge points exist
2024-03-11 04:18:45.831  [    1,61,04:18:45.831,DBG] SCAVENGING: Creating the first scavenge point.
2024-03-11 04:18:45.836  [    1,61,04:18:45.836,INF] SCAVENGING: Adding new scavenge point #0 with threshold 0...
2024-03-11 04:18:46.182  [    1,55,04:18:46.181,INF] SCAVENGING: Added new scavenge point.
2024-03-11 04:18:46.681  [    1,62,04:18:46.681,INF] SCAVENGING: Getting latest scavenge point...
2024-03-11 04:18:46.685  [    1,62,04:18:46.683,INF] SCAVENGING: Latest scavenge point found is "SP-0. Position: 6,397,430,643, EffectiveNow: 03/11/2024 04:18:45, Threshold: 0."
2024-03-11 04:18:46.685  [    1,62,04:18:46.685,DBG] SCAVENGING: Scavenge Accumulation Phase Started.
2024-03-11 04:18:46.686  [    1,62,04:18:46.686,DBG] SCAVENGING: Started new scavenge accumulation phase: "beginning of log" to "SP-0"
2024-03-11 04:18:46.730  [    1,62,04:18:46.729,DBG] SCAVENGING: Accumulating from checkpoint: "Accumulating SP-0 done None"
2024-03-11 04:18:47.448  [    1,62,04:18:47.448,DBG] SCAVENGING: Accumulated 499,457 records (499,447 originals, 10 metadatas, 0 tombstones) in chunk 0 in 00:00:00.7024920. 710,978.92 records per second. Commit: 00:00:00.0142754. Chunk total: 00:00:00.7180381
2024-03-11 04:18:47.479  [    1,62,04:18:47.479,DBG] SCAVENGING: ScavengeState size: 4.62 MB. Cache size: 2,147.48 MB. Memory usage: 4.98 MB
2024-03-11 04:18:47.480  [    1,62,04:18:47.479,DBG] SCAVENGING: CollisionDetector stats: 47,129 new streams. 0 new collisions. 0 old collisions. 452,338 hits. 47,129 misses.
2024-03-11 04:18:47.965  [    1,62,04:18:47.965,DBG] SCAVENGING: Accumulated 499,397 records (499,169 originals, 228 metadatas, 0 tombstones) in chunk 1 in 00:00:00.4728126. 1,056,226.08 records per second. Commit: 00:00:00.0127793. Chunk total: 00:00:00.4856267
2024-03-11 04:18:47.995  [    1,62,04:18:47.995,DBG] SCAVENGING: CollisionDetector stats: 5,992 new streams. 0 new collisions. 0 old collisions. 493,633 hits. 5,992 misses.
2024-03-11 04:18:47.995  [    1,62,04:18:47.995,DBG] SCAVENGING: ScavengeState size: 5.18 MB. Cache size: 2,147.48 MB. Memory usage: 5.54 MB
2024-03-11 04:18:48.500  [    1,62,04:18:48.499,DBG] SCAVENGING: Accumulated 517,806 records (517,607 originals, 199 metadatas, 0 tombstones) in chunk 2 in 00:00:00.4914611. 1,053,605.26 records per second. Commit: 00:00:00.0131900. Chunk total: 00:00:00.5046622
2024-03-11 04:18:48.528  [    1,62,04:18:48.528,DBG] SCAVENGING: ScavengeState size: 5.51 MB. Cache size: 2,147.48 MB. Memory usage: 5.88 MB
2024-03-11 04:18:48.528  [    1,62,04:18:48.528,DBG] SCAVENGING: CollisionDetector stats: 3,602 new streams. 0 new collisions. 0 old collisions. 514,403 hits. 3,602 misses.
2024-03-11 04:18:49.004  [    1,62,04:18:49.003,DBG] SCAVENGING: Accumulated 489,368 records (489,005 originals, 363 metadatas, 0 tombstones) in chunk 3 in 00:00:00.4620433. 1,059,138.83 records per second. Commit: 00:00:00.0130181. Chunk total: 00:00:00.4750745
2024-03-11 04:18:49.033  [    1,62,04:18:49.033,DBG] SCAVENGING: ScavengeState size: 5.77 MB. Cache size: 2,147.48 MB. Memory usage: 6.15 MB
2024-03-11 04:18:49.033  [    1,62,04:18:49.033,DBG] SCAVENGING: CollisionDetector stats: 3,471 new streams. 0 new collisions. 0 old collisions. 486,260 hits. 3,471 misses.
2024-03-11 04:18:49.526  [    1,62,04:18:49.526,DBG] SCAVENGING: Accumulated 516,165 records (515,446 originals, 719 metadatas, 0 tombstones) in chunk 4 in 00:00:00.4805108. 1,074,200.62 records per second. Commit: 00:00:00.0127962. Chunk total: 00:00:00.4933323
2024-03-11 04:18:49.556  [    1,62,04:18:49.556,DBG] SCAVENGING: ScavengeState size: 6.03 MB. Cache size: 2,147.48 MB. Memory usage: 6.42 MB
2024-03-11 04:18:49.556  [    1,62,04:18:49.556,DBG] SCAVENGING: CollisionDetector stats: 2,595 new streams. 0 new collisions. 0 old collisions. 514,289 hits. 2,595 misses.
2024-03-11 04:18:50.045  [    1,62,04:18:50.045,DBG] SCAVENGING: Accumulated 528,103 records (527,589 originals, 514 metadatas, 0 tombstones) in chunk 5 in 00:00:00.4757281. 1,110,094.19 records per second. Commit: 00:00:00.0129586. Chunk total: 00:00:00.4887022
2024-03-11 04:18:50.076  [    1,62,04:18:50.075,DBG] SCAVENGING: CollisionDetector stats: 2,214 new streams. 0 new collisions. 0 old collisions. 526,403 hits. 2,214 misses.
2024-03-11 04:18:50.076  [    1,62,04:18:50.075,DBG] SCAVENGING: ScavengeState size: 6.23 MB. Cache size: 2,147.48 MB. Memory usage: 6.62 MB
2024-03-11 04:18:50.575  [    1,62,04:18:50.575,DBG] SCAVENGING: Accumulated 458,499 records (457,905 originals, 594 metadatas, 0 tombstones) in chunk 6 in 00:00:00.4869257. 941,620.05 records per second. Commit: 00:00:00.0129210. Chunk total: 00:00:00.4998699
2024-03-11 04:18:50.606  [    1,62,04:18:50.606,DBG] SCAVENGING: ScavengeState size: 6.46 MB. Cache size: 2,147.48 MB. Memory usage: 6.86 MB
2024-03-11 04:18:50.606  [    1,62,04:18:50.606,DBG] SCAVENGING: CollisionDetector stats: 3,297 new streams. 0 new collisions. 0 old collisions. 455,796 hits. 3,297 misses.
2024-03-11 04:18:51.151  [    1,62,04:18:51.151,DBG] SCAVENGING: Accumulated 514,930 records (513,993 originals, 937 metadatas, 0 tombstones) in chunk 7 in 00:00:00.5315549. 968,724.02 records per second. Commit: 00:00:00.0129101. Chunk total: 00:00:00.5444766
2024-03-11 04:18:51.181  [    1,62,04:18:51.181,DBG] SCAVENGING: ScavengeState size: 6.82 MB. Cache size: 2,147.48 MB. Memory usage: 7.22 MB
2024-03-11 04:18:51.182  [    1,62,04:18:51.181,DBG] SCAVENGING: CollisionDetector stats: 2,963 new streams. 0 new collisions. 0 old collisions. 512,904 hits. 2,963 misses.
2024-03-11 04:18:51.736  [    1,62,04:18:51.736,DBG] SCAVENGING: Accumulated 501,471 records (500,853 originals, 618 metadatas, 0 tombstones) in chunk 8 in 00:00:00.5412406. 926,521.40 records per second. Commit: 00:00:00.0129775. Chunk total: 00:00:00.5542323
2024-03-11 04:18:51.766  [    1,62,04:18:51.766,DBG] SCAVENGING: ScavengeState size: 7.05 MB. Cache size: 2,147.48 MB. Memory usage: 7.46 MB
2024-03-11 04:18:51.766  [    1,62,04:18:51.766,DBG] SCAVENGING: CollisionDetector stats: 2,377 new streams. 0 new collisions. 0 old collisions. 499,712 hits. 2,377 misses.
2024-03-11 04:18:52.234  [    1,62,04:18:52.234,DBG] SCAVENGING: Accumulated 457,289 records (456,833 originals, 456 metadatas, 0 tombstones) in chunk 9 in 00:00:00.4548642. 1,005,330.82 records per second. Commit: 00:00:00.0133829. Chunk total: 00:00:00.4682668
2024-03-11 04:18:52.264  [    1,62,04:18:52.264,DBG] SCAVENGING: ScavengeState size: 7.14 MB. Cache size: 2,147.48 MB. Memory usage: 7.56 MB
2024-03-11 04:18:52.264  [    1,62,04:18:52.264,DBG] SCAVENGING: CollisionDetector stats: 1,456 new streams. 0 new collisions. 0 old collisions. 456,289 hits. 1,456 misses.
2024-03-11 04:18:52.795  [    1,62,04:18:52.795,DBG] SCAVENGING: Accumulated 509,068 records (508,314 originals, 754 metadatas, 0 tombstones) in chunk 10 in 00:00:00.5180516. 982,658.87 records per second. Commit: 00:00:00.0126367. Chunk total: 00:00:00.5307010
2024-03-11 04:18:52.826  [    1,62,04:18:52.825,DBG] SCAVENGING: ScavengeState size: 7.24 MB. Cache size: 2,147.48 MB. Memory usage: 7.67 MB
2024-03-11 04:18:52.826  [    1,62,04:18:52.825,DBG] SCAVENGING: CollisionDetector stats: 1,527 new streams. 0 new collisions. 0 old collisions. 508,295 hits. 1,527 misses.
2024-03-11 04:18:53.387  [    1,62,04:18:53.387,DBG] SCAVENGING: Accumulated 530,496 records (528,650 originals, 1,846 metadatas, 0 tombstones) in chunk 11 in 00:00:00.5482648. 967,590.84 records per second. Commit: 00:00:00.0130161. Chunk total: 00:00:00.5612916
2024-03-11 04:18:53.418  [    1,62,04:18:53.417,DBG] SCAVENGING: ScavengeState size: 7.34 MB. Cache size: 2,147.48 MB. Memory usage: 7.77 MB
2024-03-11 04:18:53.418  [    1,62,04:18:53.417,DBG] SCAVENGING: CollisionDetector stats: 1,623 new streams. 0 new collisions. 0 old collisions. 530,719 hits. 1,623 misses.
2024-03-11 04:18:54.069  [    1,62,04:18:54.069,DBG] SCAVENGING: Accumulated 515,793 records (515,684 originals, 109 metadatas, 0 tombstones) in chunk 12 in 00:00:00.6387954. 807,446.33 records per second. Commit: 00:00:00.0130232. Chunk total: 00:00:00.6518209
2024-03-11 04:18:54.100  [    1,62,04:18:54.100,DBG] SCAVENGING: CollisionDetector stats: 1,305 new streams. 0 new collisions. 0 old collisions. 514,597 hits. 1,305 misses.
2024-03-11 04:18:54.100  [    1,62,04:18:54.100,DBG] SCAVENGING: ScavengeState size: 7.50 MB. Cache size: 2,147.48 MB. Memory usage: 7.88 MB
2024-03-11 04:20:50.521  [    1,62,04:20:50.521,DBG] SCAVENGING: Accumulated 532,925 records (531,348 originals, 1,577 metadatas, 0 tombstones) in chunk 13 in 00:01:56.4067577. 4,578.13 records per second. Commit: 00:00:00.0140616. Chunk total: 00:01:56.4209826
2024-03-11 04:20:50.551  [    1,62,04:20:50.551,DBG] SCAVENGING: ScavengeState size: 7.63 MB. Cache size: 2,147.48 MB. Memory usage: 8.02 MB
2024-03-11 04:20:50.551  [    1,62,04:20:50.551,DBG] SCAVENGING: CollisionDetector stats: 1,214 new streams. 0 new collisions. 0 old collisions. 533,288 hits. 1,214 misses.
2024-03-11 04:23:21.053  [    1,62,04:23:21.052,DBG] SCAVENGING: Accumulated 430,256 records (429,092 originals, 1,164 metadatas, 0 tombstones) in chunk 14 in 00:02:30.4870692. 2,859.09 records per second. Commit: 00:00:00.0141247. Chunk total: 00:02:30.5012133
2024-03-11 04:23:21.084  [    1,62,04:23:21.084,DBG] SCAVENGING: ScavengeState size: 7.70 MB. Cache size: 2,147.48 MB. Memory usage: 8.09 MB
2024-03-11 04:23:21.084  [    1,62,04:23:21.084,DBG] SCAVENGING: CollisionDetector stats: 1,074 new streams. 0 new collisions. 0 old collisions. 430,346 hits. 1,074 misses.
2024-03-11 04:26:02.778  [    1,62,04:26:02.778,DBG] SCAVENGING: Accumulated 480,978 records (480,871 originals, 107 metadatas, 0 tombstones) in chunk 15 in 00:02:41.6806061. 2,974.87 records per second. Commit: 00:00:00.0137451. Chunk total: 00:02:41.6943615
2024-03-11 04:26:02.808  [    1,62,04:26:02.808,DBG] SCAVENGING: CollisionDetector stats: 1,341 new streams. 0 new collisions. 0 old collisions. 479,744 hits. 1,341 misses.
2024-03-11 04:26:02.808  [    1,62,04:26:02.808,DBG] SCAVENGING: ScavengeState size: 7.86 MB. Cache size: 2,147.48 MB. Memory usage: 8.26 MB
2024-03-11 04:28:41.794  [    1,62,04:28:41.794,DBG] SCAVENGING: Accumulated 467,705 records (467,625 originals, 80 metadatas, 0 tombstones) in chunk 16 in 00:02:38.8254712. 2,944.77 records per second. Commit: 00:00:00.1606316. Chunk total: 00:02:38.9861059
2024-03-11 04:28:41.809  [    1,62,04:28:41.809,DBG] SCAVENGING: ScavengeState size: 7.96 MB. Cache size: 2,147.48 MB. Memory usage: 8.37 MB
2024-03-11 04:28:41.809  [    1,62,04:28:41.809,DBG] SCAVENGING: CollisionDetector stats: 1,046 new streams. 0 new collisions. 0 old collisions. 466,739 hits. 1,046 misses.
2024-03-11 04:31:22.028  [    1,62,04:31:22.027,DBG] SCAVENGING: Accumulated 474,331 records (473,076 originals, 1,255 metadatas, 0 tombstones) in chunk 17 in 00:02:40.1698216. 2,961.43 records per second. Commit: 00:00:00.0489126. Chunk total: 00:02:40.2187558
2024-03-11 04:31:22.058  [    1,62,04:31:22.058,DBG] SCAVENGING: CollisionDetector stats: 1,229 new streams. 0 new collisions. 0 old collisions. 474,357 hits. 1,229 misses.
2024-03-11 04:31:22.058  [    1,62,04:31:22.058,DBG] SCAVENGING: ScavengeState size: 8.06 MB. Cache size: 2,147.48 MB. Memory usage: 8.47 MB
2024-03-11 04:33:52.857  [    1,62,04:33:52.856,DBG] SCAVENGING: Accumulated 425,658 records (425,554 originals, 104 metadatas, 0 tombstones) in chunk 18 in 00:02:30.7844720. 2,822.96 records per second. Commit: 00:00:00.0138809. Chunk total: 00:02:30.7983664
2024-03-11 04:33:52.887  [    1,62,04:33:52.887,DBG] SCAVENGING: ScavengeState size: 8.16 MB. Cache size: 2,147.48 MB. Memory usage: 8.57 MB
2024-03-11 04:33:52.887  [    1,62,04:33:52.887,DBG] SCAVENGING: CollisionDetector stats: 1,030 new streams. 0 new collisions. 0 old collisions. 424,732 hits. 1,030 misses.
2024-03-11 04:36:00.206  [    1,62,04:36:00.206,DBG] SCAVENGING: Accumulated 282,241 records (279,332 originals, 2,909 metadatas, 0 tombstones) in chunk 19 in 00:02:07.3041633. 2,217.06 records per second. Commit: 00:00:00.0152376. Chunk total: 00:02:07.3194224
2024-03-11 04:36:00.238  [    1,62,04:36:00.238,DBG] SCAVENGING: ScavengeState size: 8.36 MB. Cache size: 2,147.48 MB. Memory usage: 8.78 MB
2024-03-11 04:36:00.238  [    1,62,04:36:00.238,DBG] SCAVENGING: CollisionDetector stats: 674 new streams. 0 new collisions. 0 old collisions. 284,476 hits. 674 misses.
2024-03-11 04:38:14.658  [    1,62,04:38:14.658,DBG] SCAVENGING: Accumulated 320,040 records (319,983 originals, 57 metadatas, 0 tombstones) in chunk 20 in 00:02:14.4072633. 2,381.12 records per second. Commit: 00:00:00.0131122. Chunk total: 00:02:14.4203860
2024-03-11 04:38:14.688  [    1,62,04:38:14.688,DBG] SCAVENGING: CollisionDetector stats: 528 new streams. 0 new collisions. 0 old collisions. 319,569 hits. 528 misses.
2024-03-11 04:38:14.688  [    1,62,04:38:14.688,DBG] SCAVENGING: ScavengeState size: 8.39 MB. Cache size: 2,147.48 MB. Memory usage: 8.81 MB
2024-03-11 04:40:36.202  [    1,62,04:40:36.201,DBG] SCAVENGING: Accumulated 364,219 records (362,624 originals, 1,595 metadatas, 0 tombstones) in chunk 21 in 00:02:21.3462921. 2,576.78 records per second. Commit: 00:00:00.1668804. Chunk total: 00:02:21.5131965
2024-03-11 04:40:36.231  [    1,62,04:40:36.231,DBG] SCAVENGING: ScavengeState size: 8.45 MB. Cache size: 2,147.48 MB. Memory usage: 8.89 MB
2024-03-11 04:40:36.231  [    1,62,04:40:36.231,DBG] SCAVENGING: CollisionDetector stats: 984 new streams. 0 new collisions. 0 old collisions. 364,830 hits. 984 misses.
2024-03-11 04:41:25.831  [    1,62,04:41:25.831,DBG] SCAVENGING: Accumulated 392,858 records (392,341 originals, 517 metadatas, 0 tombstones) in chunk 22 in 00:00:49.4027998. 7,952.14 records per second. Commit: 00:00:00.1971231. Chunk total: 00:00:49.5999388
2024-03-11 04:41:25.860  [    1,62,04:41:25.860,DBG] SCAVENGING: ScavengeState size: 8.55 MB. Cache size: 2,147.48 MB. Memory usage: 8.99 MB
2024-03-11 04:41:25.860  [    1,62,04:41:25.860,DBG] SCAVENGING: CollisionDetector stats: 870 new streams. 0 new collisions. 0 old collisions. 392,505 hits. 870 misses.
2024-03-11 04:41:26.373  [    1,62,04:41:26.372,DBG] SCAVENGING: Accumulated 323,482 records (320,428 originals, 3,054 metadatas, 0 tombstones) in chunk 23 in 00:00:00.3129920. 1,033,515.23 records per second. Commit: 00:00:00.1993302. Chunk total: 00:00:00.5123382
2024-03-11 04:41:26.403  [    1,62,04:41:26.403,DBG] SCAVENGING: CollisionDetector stats: 622 new streams. 0 new collisions. 0 old collisions. 325,914 hits. 622 misses.
2024-03-11 04:41:26.403  [    1,62,04:41:26.403,DBG] SCAVENGING: ScavengeState size: 8.59 MB. Cache size: 2,147.48 MB. Memory usage: 9.03 MB
2024-03-11 04:41:26.415  [    1,62,04:41:26.415,DBG] SCAVENGING: ScavengeState size: 8.59 MB. Cache size: 2,147.48 MB. Memory usage: 9.03 MB
2024-03-11 04:41:26.415  [    1,62,04:41:26.415,DBG] SCAVENGING: Rested 00:00:00 out of 00:22:41.7115393. 100.00 percent active.
2024-03-11 04:41:26.416  [    1,62,04:41:26.415,DBG] SCAVENGING: Scavenge Accumulation Phase Completed. Took 00:22:39.7175120.
2024-03-11 04:41:26.417  [    1,62,04:41:26.417,DBG] SCAVENGING: 0 KNOWN COLLISIONS
2024-03-11 04:41:26.417  [    1,62,04:41:26.417,DBG] SCAVENGING: Scavenge Calculation Phase Started.
2024-03-11 04:41:26.418  [    1,62,04:41:26.418,DBG] SCAVENGING: Started new scavenge calculation phase for "SP-0"
2024-03-11 04:41:26.454  [    1,62,04:41:26.453,DBG] SCAVENGING: Calculating from checkpoint: "Calculating SP-0 done None"
2024-03-11 04:42:17.208  [    1,62,04:42:17.208,DBG] SCAVENGING: Calculated in period: 1,785 streams in 00:00:50.7541629. 35.17 streams per second
2024-03-11 04:42:17.208  [    1,62,04:42:17.208,DBG] SCAVENGING: Calculated in total: 1,785 streams in 00:00:50.7541992. 35.17 streams per second
2024-03-11 04:42:17.238  [    1,62,04:42:17.238,DBG] SCAVENGING: Calculated in grand total (including rests): 1,785 streams in 00:00:50.7844377. 35.15 streams per second
2024-03-11 04:42:17.250  [    1,62,04:42:17.250,DBG] SCAVENGING: Rested 00:00:00 out of 00:23:32.5464094. 100.00 percent active.
2024-03-11 04:42:17.250  [    1,62,04:42:17.250,DBG] SCAVENGING: Scavenge Calculation Phase Completed. Took 00:00:50.8206930.
2024-03-11 04:42:17.250  [    1,62,04:42:17.250,DBG] SCAVENGING: ScavengeState size: 8.59 MB. Cache size: 2,147.48 MB. Memory usage: 8.98 MB
2024-03-11 04:42:17.251  [    1,62,04:42:17.251,DBG] SCAVENGING: Scavenge Chunk execution Phase Started.
2024-03-11 04:42:17.251  [    1,62,04:42:17.251,DBG] SCAVENGING: Started new scavenge chunk execution phase for "SP-0"
2024-03-11 04:42:17.286  [    1,62,04:42:17.286,DBG] SCAVENGING: Executing chunks from checkpoint: "Executing chunks for SP-0 done None"
2024-03-11 04:42:17.299  [    1,62,04:42:17.299,DBG] SCAVENGING: Setting page size to 32,768 bytes.
2024-03-11 04:42:17.520  [    1,62,04:42:17.520,DBG] SCAVENGING: Setting page size to 32,768 bytes.
2024-03-11 04:42:17.704  [    1,62,04:42:17.704,DBG] SCAVENGING: Setting page size to 32,768 bytes.
2024-03-11 04:42:17.888  [    1,62,04:42:17.888,DBG] SCAVENGING: Setting page size to 32,768 bytes.
3

LOG 2

2024-03-11 04:42:18.086  [    1,91,04:42:18.086,DBG] SCAVENGING: Started to scavenge physical chunk: "#1-1 (chunk-000001.000000)" with weight 461,314. 1 => 1 (268435456 => 536870912)
2024-03-11 04:42:18.087  [    1,98,04:42:18.087,DBG] SCAVENGING: Started to scavenge physical chunk: "#0-0 (chunk-000000.000000)" with weight 493,428. 0 => 0 (0 => 268435456)
2024-03-11 04:42:18.144  [    1,91,04:42:18.144,DBG] SCAVENGING: Resulting temp chunk file: "321451e7-acfa-407c-bb32-aaf348b8a68f.scavenge.tmp".
2024-03-11 04:42:18.157  [    1,98,04:42:18.157,DBG] SCAVENGING: Resulting temp chunk file: "67dba492-7037-4d7a-afb5-218473f87089.scavenge.tmp".
2024-03-11 04:42:18.848  [    1, 6,04:42:18.848,DBG] SCAVENGING: Started to scavenge physical chunk: "#2-2 (chunk-000002.000000)" with weight 522,082. 2 => 2 (536870912 => 805306368)
2024-03-11 04:42:18.894  [    1, 6,04:42:18.894,DBG] SCAVENGING: Resulting temp chunk file: "97d4936d-59b9-4894-8505-3089433c5b75.scavenge.tmp".
2024-03-11 04:42:19.842  [    1,95,04:42:19.842,DBG] SCAVENGING: Started to scavenge physical chunk: "#3-3 (chunk-000003.000000)" with weight 484,426. 3 => 3 (805306368 => 1073741824)
2024-03-11 04:42:19.898  [    1,95,04:42:19.898,DBG] SCAVENGING: Resulting temp chunk file: "2c5621ce-4933-42b5-a442-cb131104c387.scavenge.tmp".
2024-03-11 06:14:41.215  [    1,95,06:14:41.215,DBG] SCAVENGING: Scavenging "#3-3 (chunk-000003.000000)" traversed 489,371.  Kept 247,158. Discarded 242,213
2024-03-11 06:14:42.509  [    1,95,06:14:42.509,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 06:14:42.744  [    1,95,06:14:42.744,DBG] SCAVENGING: Started to scavenge physical chunk: "#4-4 (chunk-000004.000000)" with weight 549,284. 4 => 4 (1073741824 => 1342177280)
2024-03-11 06:14:42.804  [    1,95,06:14:42.804,DBG] SCAVENGING: Resulting temp chunk file: "ad2b0955-1652-414f-a8e7-181cfc26a87a.scavenge.tmp".
2024-03-11 06:21:38.309  [    1,91,06:21:38.309,DBG] SCAVENGING: Scavenging "#1-1 (chunk-000001.000000)" traversed 499,482.  Kept 268,825. Discarded 230,657
2024-03-11 06:21:39.693  [    1,91,06:21:39.692,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 06:21:42.910  [    1,91,06:21:42.910,DBG] SCAVENGING: Started to scavenge physical chunk: "#5-5 (chunk-000005.000000)" with weight 531,564. 5 => 5 (1342177280 => 1610612736)
2024-03-11 06:21:42.969  [    1,91,06:21:42.969,DBG] SCAVENGING: Resulting temp chunk file: "d3b47ae8-7ca9-4994-ae3b-58835445368c.scavenge.tmp".
2024-03-11 06:23:26.319  [    1, 6,06:23:26.318,DBG] SCAVENGING: Scavenging "#2-2 (chunk-000002.000000)" traversed 517,811.  Kept 256,770. Discarded 261,041
2024-03-11 06:23:27.623  [    1, 6,06:23:27.623,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 06:23:28.056  [    1, 6,06:23:28.056,DBG] SCAVENGING: Started to scavenge physical chunk: "#6-6 (chunk-000006.000000)" with weight 464,762. 6 => 6 (1610612736 => 1879048192)
2024-03-11 06:23:28.106  [    1, 6,06:23:28.106,DBG] SCAVENGING: Resulting temp chunk file: "2d2169f9-a2fe-471c-8c84-8364157013dd.scavenge.tmp".
2024-03-11 06:40:38.677  [    1,98,06:40:38.677,DBG] SCAVENGING: Scavenging "#0-0 (chunk-000000.000000)" traversed 499,459.  Kept 252,745. Discarded 246,714
2024-03-11 06:40:39.990  [    1,98,06:40:39.990,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 06:40:43.361  [    1,98,06:40:43.361,DBG] SCAVENGING: Started to scavenge physical chunk: "#7-7 (chunk-000007.000000)" with weight 590,182. 7 => 7 (1879048192 => 2147483648)
2024-03-11 06:40:43.419  [    1,98,06:40:43.419,DBG] SCAVENGING: Resulting temp chunk file: "3720026a-865c-40d3-9eac-0c7b385fb8e5.scavenge.tmp".
2024-03-11 07:45:21.011  [    1,95,07:45:21.010,DBG] SCAVENGING: Scavenging "#4-4 (chunk-000004.000000)" traversed 516,169.  Kept 241,527. Discarded 274,642
2024-03-11 07:45:22.339  [    1,95,07:45:22.339,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 07:45:24.905  [    1,95,07:45:24.905,DBG] SCAVENGING: Started to scavenge physical chunk: "#8-8 (chunk-000008.000000)" with weight 530,316. 8 => 8 (2147483648 => 2415919104)
2024-03-11 07:45:24.963  [    1,95,07:45:24.963,DBG] SCAVENGING: Resulting temp chunk file: "c81a9c85-08d3-4086-932c-fd624199a725.scavenge.tmp".
2024-03-11 07:46:56.240  [    1, 6,07:46:56.239,DBG] SCAVENGING: Scavenging "#6-6 (chunk-000006.000000)" traversed 458,499.  Kept 226,118. Discarded 232,381
2024-03-11 07:46:57.241  [    1, 6,07:46:57.241,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 07:47:12.838  [    1, 6,07:47:12.838,DBG] SCAVENGING: Started to scavenge physical chunk: "#9-9 (chunk-000009.000000)" with weight 442,472. 9 => 9 (2415919104 => 2684354560)
2024-03-11 07:47:12.884  [    1, 6,07:47:12.884,DBG] SCAVENGING: Resulting temp chunk file: "733b23a2-c331-4ff6-b129-21e871d16fcc.scavenge.tmp".
2024-03-11 07:51:16.392  [    1,91,07:51:16.392,DBG] SCAVENGING: Scavenging "#5-5 (chunk-000005.000000)" traversed 528,103.  Kept 262,321. Discarded 265,782
2024-03-11 07:51:17.720  [    1,91,07:51:17.719,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 07:51:25.166  [    1,81,07:51:25.166,DBG] SCAVENGING: Started to scavenge physical chunk: "#10-10 (chunk-000010.000000)" with weight 505,888. 10 => 10 (2684354560 => 2952790016)
2024-03-11 07:51:25.225  [    1,81,07:51:25.225,DBG] SCAVENGING: Resulting temp chunk file: "a2252e00-a27d-4a7f-84c3-66442046863d.scavenge.tmp".
2024-03-11 08:04:55.579  [    1,98,08:04:55.579,DBG] SCAVENGING: Scavenging "#7-7 (chunk-000007.000000)" traversed 514,974.  Kept 219,883. Discarded 295,091
2024-03-11 08:04:56.567  [    1,98,08:04:56.566,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 08:04:56.856  [    1,98,08:04:56.856,DBG] SCAVENGING: Started to scavenge physical chunk: "#11-11 (chunk-000011.000000)" with weight 568,152. 11 => 11 (2952790016 => 3221225472)
2024-03-11 08:04:56.903  [    1,98,08:04:56.903,DBG] SCAVENGING: Resulting temp chunk file: "cf526d5b-295c-43b0-a0c7-e83adb15b7bc.scavenge.tmp".
2024-03-11 09:02:51.187  [    1, 6,09:02:51.187,DBG] SCAVENGING: Scavenging "#9-9 (chunk-000009.000000)" traversed 457,292.  Kept 236,056. Discarded 221,236
2024-03-11 09:02:52.513  [    1, 6,09:02:52.513,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 09:02:54.968  [    1, 6,09:02:54.968,DBG] SCAVENGING: Started to scavenge physical chunk: "#12-12 (chunk-000012.000000)" with weight 524,552. 12 => 12 (3221225472 => 3489660928)
2024-03-11 09:02:55.026  [    1, 6,09:02:55.026,DBG] SCAVENGING: Resulting temp chunk file: "0d6e29d4-3f4f-4999-9c9e-1f23470ad790.scavenge.tmp".
2024-03-11 09:03:35.427  [    1,95,09:03:35.427,DBG] SCAVENGING: Scavenging "#8-8 (chunk-000008.000000)" traversed 501,474.  Kept 236,316. Discarded 265,158
2024-03-11 09:03:36.634  [    1,95,09:03:36.634,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 09:03:54.838  [    1,85,09:03:54.837,DBG] SCAVENGING: Started to scavenge physical chunk: "#13-13 (chunk-000013.000000)" with weight 572,492. 13 => 13 (3489660928 => 3758096384)
2024-03-11 09:03:54.894  [    1,85,09:03:54.893,DBG] SCAVENGING: Resulting temp chunk file: "56957224-27d1-4851-a495-f405a22c737f.scavenge.tmp".
2024-03-11 09:09:58.515  [    1,81,09:09:58.514,DBG] SCAVENGING: Scavenging "#10-10 (chunk-000010.000000)" traversed 509,076.  Kept 256,132. Discarded 252,944
2024-03-11 09:09:59.763  [    1,81,09:09:59.763,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 09:10:12.929  [    1,81,09:10:12.928,DBG] SCAVENGING: Started to scavenge physical chunk: "#14-14 (chunk-000014.000000)" with weight 444,898. 14 => 14 (3758096384 => 4026531840)
2024-03-11 09:10:12.986  [    1,81,09:10:12.986,DBG] SCAVENGING: Resulting temp chunk file: "ed099f94-278d-4bb0-9f8a-3ab015359e27.scavenge.tmp".
2024-03-11 09:23:30.366  [    1,98,09:23:30.366,DBG] SCAVENGING: Scavenging "#11-11 (chunk-000011.000000)" traversed 530,501.  Kept 246,425. Discarded 284,076
2024-03-11 09:23:31.609  [    1,98,09:23:31.608,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 09:23:54.901  [    1,88,09:23:54.901,DBG] SCAVENGING: Started to scavenge physical chunk: "#15-15 (chunk-000015.000000)" with weight 457,624. 15 => 15 (4026531840 => 4294967296)
2024-03-11 09:23:54.948  [    1,88,09:23:54.948,DBG] SCAVENGING: Resulting temp chunk file: "2a07d4b3-3a50-4f32-acb1-129e1bd5a98f.scavenge.tmp".
2024-03-11 10:14:03.134  [    1,81,10:14:03.133,DBG] SCAVENGING: Scavenging "#14-14 (chunk-000014.000000)" traversed 430,257.  Kept 207,808. Discarded 222,449
2024-03-11 10:14:04.175  [    1,81,10:14:04.175,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 10:14:12.903  [    1,81,10:14:12.903,DBG] SCAVENGING: Started to scavenge physical chunk: "#16-16 (chunk-000016.000000)" with weight 444,838. 16 => 16 (4294967296 => 4563402752)
2024-03-11 10:14:12.961  [    1,81,10:14:12.961,DBG] SCAVENGING: Resulting temp chunk file: "891aa5d3-712c-4568-bc4b-bf0436ec2a42.scavenge.tmp".
2024-03-11 10:14:14.956  [    1, 6,10:14:14.955,DBG] SCAVENGING: Scavenging "#12-12 (chunk-000012.000000)" traversed 515,796.  Kept 253,520. Discarded 262,276
2024-03-11 10:14:16.237  [    1, 6,10:14:16.237,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 10:14:24.857  [    1, 6,10:14:24.857,DBG] SCAVENGING: Started to scavenge physical chunk: "#17-17 (chunk-000017.000000)" with weight 445,000. 17 => 17 (4563402752 => 4831838208)
2024-03-11 10:14:24.915  [    1, 6,10:14:24.915,DBG] SCAVENGING: Resulting temp chunk file: "98de31cc-aac2-43a4-9d07-59f7ab8d4f29.scavenge.tmp".
2024-03-11 10:16:09.236  [    1,85,10:16:09.236,DBG] SCAVENGING: Scavenging "#13-13 (chunk-000013.000000)" traversed 532,929.  Kept 246,683. Discarded 286,246
2024-03-11 10:16:10.503  [    1,85,10:16:10.502,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 10:16:13.159  [    1,87,10:16:13.159,DBG] SCAVENGING: Started to scavenge physical chunk: "#18-18 (chunk-000018.000000)" with weight 402,610. 18 => 18 (4831838208 => 5100273664)
2024-03-11 10:16:13.218  [    1,87,10:16:13.217,DBG] SCAVENGING: Resulting temp chunk file: "14ebd6aa-5686-47e1-b33e-5f6265382612.scavenge.tmp".
2024-03-11 10:35:19.389  [    1,88,10:35:19.389,DBG] SCAVENGING: Scavenging "#15-15 (chunk-000015.000000)" traversed 480,981.  Kept 252,169. Discarded 228,812
2024-03-11 10:35:20.683  [    1,88,10:35:20.683,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 10:35:25.172  [    1,58,10:35:25.172,DBG] SCAVENGING: Started to scavenge physical chunk: "#19-19 (chunk-000019.000000)" with weight 279,076. 19 => 19 (5100273664 => 5368709120)
2024-03-11 10:35:25.220  [    1,58,10:35:25.220,DBG] SCAVENGING: Resulting temp chunk file: "4289c707-4df2-4de3-a9aa-58f07359ce58.scavenge.tmp".
2024-03-11 11:19:19.732  [    1,58,11:19:19.732,DBG] SCAVENGING: Scavenging "#19-19 (chunk-000019.000000)" traversed 282,241.  Kept 142,703. Discarded 139,538
2024-03-11 11:19:20.586  [    1,58,11:19:20.586,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 11:19:24.958  [    1,58,11:19:24.957,DBG] SCAVENGING: Started to scavenge physical chunk: "#20-20 (chunk-000020.000000)" with weight 273,793. 20 => 20 (5368709120 => 5637144576)
2024-03-11 11:19:25.015  [    1,58,11:19:25.015,DBG] SCAVENGING: Resulting temp chunk file: "6f6785be-8d54-4b3c-a854-a8d14a4e97a2.scavenge.tmp".
2024-03-11 11:21:01.591  [    1,87,11:21:01.590,DBG] SCAVENGING: Scavenging "#18-18 (chunk-000018.000000)" traversed 425,659.  Kept 224,354. Discarded 201,305
2024-03-11 11:21:02.663  [    1,87,11:21:02.663,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 11:21:23.895  [    1,87,11:21:23.895,DBG] SCAVENGING: Started to scavenge physical chunk: "#21-21 (chunk-000021.000000)" with weight 287,208. 21 => 21 (5637144576 => 5905580032)
2024-03-11 11:21:23.947  [    1,87,11:21:23.947,DBG] SCAVENGING: Resulting temp chunk file: "10c26d00-f22a-478e-91ea-b29fa0a61d25.scavenge.tmp".
2024-03-11 11:24:31.515  [    1,81,11:24:31.515,DBG] SCAVENGING: Scavenging "#16-16 (chunk-000016.000000)" traversed 467,705.  Kept 245,286. Discarded 222,419
2024-03-11 11:24:32.908  [    1,81,11:24:32.908,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 11:24:56.779  [    1,94,11:24:56.779,DBG] SCAVENGING: Started to scavenge physical chunk: "#22-22 (chunk-000022.000000)" with weight 299,680. 22 => 22 (5905580032 => 6174015488)
2024-03-11 11:24:56.838  [    1,94,11:24:56.838,DBG] SCAVENGING: Resulting temp chunk file: "9c9265e5-fd56-4a95-9ad2-fb83f11f831a.scavenge.tmp".
2024-03-11 11:26:54.208  [    1, 6,11:26:54.208,DBG] SCAVENGING: Scavenging "#17-17 (chunk-000017.000000)" traversed 474,332.  Kept 251,832. Discarded 222,500
2024-03-11 11:26:55.590  [    1, 6,11:26:55.590,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 11:26:57.875  [    1,60,11:26:57.875,DBG] SCAVENGING: Started to scavenge physical chunk: "#23-23 (chunk-000023.000000)" with weight 264,548. 23 => 23 (6174015488 => 6442450944)
2024-03-11 11:26:57.933  [    1,60,11:26:57.933,DBG] SCAVENGING: Resulting temp chunk file: "fccf0e98-9c59-4367-9a58-6e30fbd08234.scavenge.tmp".
2024-03-11 12:16:05.561  [    1,58,12:16:05.560,DBG] SCAVENGING: Scavenging "#20-20 (chunk-000020.000000)" traversed 320,040.  Kept 203,853. Discarded 116,187
2024-03-11 12:16:06.785  [    1,58,12:16:06.785,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 12:19:35.561  [    1,60,12:19:35.561,DBG] SCAVENGING: Scavenging "#23-23 (chunk-000023.000000)" traversed 323,487.  Kept 191,213. Discarded 132,274
2024-03-11 12:19:36.565  [    1,60,12:19:36.565,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 12:35:34.745  [    1,87,12:35:34.744,DBG] SCAVENGING: Scavenging "#21-21 (chunk-000021.000000)" traversed 364,219.  Kept 220,615. Discarded 143,604
2024-03-11 12:35:36.064  [    1,87,12:35:36.064,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 12:57:49.237  [    1,94,12:57:49.237,DBG] SCAVENGING: Scavenging "#22-22 (chunk-000022.000000)" traversed 392,858.  Kept 243,018. Discarded 149,840
2024-03-11 12:57:50.534  [    1,94,12:57:50.533,DBG] SCAVENGING: Scavenging of chunks:
2024-03-11 12:57:50.887  [    1,62,12:57:50.886,DBG] SCAVENGING: ScavengeState size: 8.59 MB. Cache size: 2,147.48 MB. Memory usage: 4.89 MB
2024-03-11 12:57:50.888  [    1,62,12:57:50.887,DBG] SCAVENGING: Scavenge Chunk merging Phase Started.
2024-03-11 12:57:50.888  [    1,62,12:57:50.887,DBG] SCAVENGING: Started new scavenge chunk merging phase for "SP-0"
2024-03-11 12:57:50.888  [    1,62,12:57:50.886,DBG] SCAVENGING: Rested 00:00:00 out of 08:39:06.1827317. 100.00 percent active.
2024-03-11 12:57:50.888  [    1,62,12:57:50.886,DBG] SCAVENGING: Scavenge Chunk execution Phase Completed. Took 08:15:33.5539132.
2024-03-11 12:57:51.004  [    1,62,12:57:51.004,DBG] SCAVENGING: Merging chunks from checkpoint: "Merging chunks for SP-0"
2024-03-11 12:57:51.009  [    1,62,12:57:51.009,DBG] SCAVENGING: Started to merge chunks: "#18-18 (chunk-000018.000001)\n#19-19 (chunk-000019.000001)"
2024-03-11 13:02:22.763  [    1,62,13:02:22.763,DBG] SCAVENGING: Merge pass #1 completed in 00:04:31.7572230. "Some chunks" merged.
2024-03-11 13:02:22.763  [    1,62,13:02:22.763,DBG] SCAVENGING: Merge pass #2 completed in 00:00:00.0000294. "Nothing" merged.
2024-03-11 13:02:22.877  [    1,62,13:02:22.876,DBG] SCAVENGING: ScavengeState size: 8.59 MB. Cache size: 2,147.48 MB. Memory usage: 4.90 MB
2024-03-11 13:02:22.877  [    1,62,13:02:22.876,DBG] SCAVENGING: Rested 00:00:00 out of 08:43:38.1727322. 100.00 percent active.
2024-03-11 13:02:22.877  [    1,62,13:02:22.876,DBG] SCAVENGING: Scavenge Chunk merging Phase Completed. Took 00:04:31.8762882.
2024-03-11 13:02:22.878  [    1,62,13:02:22.878,DBG] SCAVENGING: Started new scavenge index execution phase for "SP-0"
2024-03-11 13:02:22.878  [    1,62,13:02:22.878,DBG] SCAVENGING: Scavenge Index execution Phase Started.
2024-03-11 13:02:22.999  [    1,62,13:02:22.999,DBG] SCAVENGING: Executing indexes from checkpoint: "Executing index for SP-0"
2024-03-11 14:47:20.293  [    1,62,14:47:20.293,DBG] SCAVENGING: Rested 00:00:00 out of 10:28:35.5887900. 100.00 percent active.
2024-03-11 14:47:20.293  [    1,62,14:47:20.293,DBG] SCAVENGING: Scavenge Index execution Phase Completed. Took 01:44:57.3841325.
2024-03-11 14:47:20.293  [    1,62,14:47:20.293,DBG] SCAVENGING: Scavenge Cleaning Phase Started.
2024-03-11 14:47:20.293  [    1,62,14:47:20.293,DBG] SCAVENGING: Started new scavenge clean up phase for "SP-0"
2024-03-11 14:47:20.293  [    1,62,14:47:20.293,DBG] SCAVENGING: ScavengeState size: 8.59 MB. Cache size: 2,147.48 MB. Memory usage: 4.89 MB
2024-03-11 14:47:20.361  [    1,62,14:47:20.361,DBG] SCAVENGING: Cleaning checkpoint: "Cleaning for SP-0"
2024-03-11 14:47:20.458  [    1,62,14:47:20.457,DBG] SCAVENGING: Deleting metastream data
2024-03-11 14:47:20.471  [    1,62,14:47:20.471,DBG] SCAVENGING: Deleting originalstream data. Deleting archived: False
2024-03-11 14:47:20.624  [    1,62,14:47:20.624,DBG] SCAVENGING: ScavengeState size: 8.59 MB. Cache size: 2,147.48 MB. Memory usage: 4.90 MB
2024-03-11 14:47:20.625  [    1,62,14:47:20.624,DBG] SCAVENGING: Scavenge Cleaning Phase Completed. Took 00:00:00.2403710.
2024-03-11 14:47:20.625  [    1,62,14:47:20.624,DBG] SCAVENGING: Rested 00:00:00 out of 10:28:35.9204966. 100.00 percent active.
2024-03-11 14:47:20.700  [    1,62,14:47:20.700,DBG] SCAVENGING: Scavenge Completed. Total time taken: 10:28:35.9920891. Total space saved: 1789109176.
2024-03-11 14:47:20.701  [    1,62,14:47:20.701,DBG] SCAVENGING: 0 KNOWN COLLISIONS
2024-03-11 14:47:20.704  [    1,62,14:47:20.704,DBG] SCAVENGING: "Accumulation" took 00:22:39.7175120
2024-03-11 14:47:20.704  [    1,62,14:47:20.704,DBG] SCAVENGING: "Calculation" took 00:00:50.8206930
2024-03-11 14:47:20.704  [    1,62,14:47:20.704,DBG] SCAVENGING: "Chunk execution" took 08:15:33.5539132
2024-03-11 14:47:20.704  [    1,62,14:47:20.704,DBG] SCAVENGING: "Chunk merging" took 00:04:31.8762882
2024-03-11 14:47:20.704  [    1,62,14:47:20.704,DBG] SCAVENGING: "Cleaning" took 00:00:00.2403710
2024-03-11 14:47:20.704  [    1,62,14:47:20.704,DBG] SCAVENGING: "Index execution" took 01:44:57.3841325
2024-03-11 14:47:20.997  [    1,62,14:47:20.997,INF] SCAVENGING: Released the chunks lock
4

Do you have a lot of ephemeral stream ?
( deleted, truncated, or with some Max Count, Max Age )

It seems that for this 1st scavenge of your DB most of the time spent was on rewriting every single chunk file.
and then merging them together ( tough on 2 if I can read the log correctly)
This is quite an IOPS intensive set of operations.
(I would recommend to monitor IOPS activity of the nodes )

SCAVENGING: “Calculation” took 00:00:50.8206930
SCAVENGING: “Chunk execution” took 08:15:33.5539132
SCAVENGING: “Chunk merging” took 00:04:31.8762882

If the data that is left in there is long term , the next scavenge should be way faster.

Also , you’re testing on a completely different type of hosting so the total runtime will probably be different in the production environment ( AKS does add their own IOPS / throughput overhead iirc ? )

The subscriptions won’t be an issue.
Once you tell the DB to scavenge, it closes the current chunk file being written to .
So any appended data is in another fille an won’t be affecting the scavenge at all .

5

Could you also try with 1 thread ?
( on a non-scavenged node)
This would help eliminate IOPS related issue

6

From the logs, I see that the processing rate dropped at some point from around 1 million records per sec to just a few thousands. Maybe, you can look at your nodes metrics at that time.
Also, I hope you have configured anti-affinity policy for the cluster pods so they don’t get scheduled on the same worker node.

That, of course, produces a massive number of events that will be scavenged.

7

One more thing is that any consequent scavenge should take a lot less time as it won’t start from the very beginning.

8

Just to underline Yves’ suggestion of trying it with one thread instead of 4.

It’s not necessarily about the IOPS, but we’ve seen poor performance during chunk execution with multiple threads once before. It would be of great interest to us if this is also a case where multiple threads has a significant impact on the performance.

9

Thanks Yves for your prompt reply.

We have thousands of ephemeral streams with the max age, and I don’t thinks it is a lot, isn’t it?
I also ran the scavenge on production, but there was no such difference. In production, we had 32 chunk files, and it took 15 hours.

I was monitoring the IOPS while running the scavenge on production. There was no throttling issue at all, so I believe that IOPS was the issue.

I hope the next scavenge would be much faster and I will get back to you after the second scavenge.

Thanks for your help.

10

Hi @timothy.coleman

It’s interesting that our case was totally opposite. Running the scavenge with a single thread was way slower than running with multiple threads.

With a single thread, it took about 3 hours to scavenge a chunk file, but it took 1 hour to scavenge a chunk file with multiple threads.

So, with 4 threads, which I believe it is the maximum, the scavenge took 1 hour to complete 4 chunk files. However, with a single thread, it took 12 hours to complete 4 chunk files… It’s very wired, isn’t it?

If you see the multiple threads slower, then you might need to check how many processors are allocated in your environment. If you have less processors than the threads count you set, it would cause the poor performance.

	Parallel.ForEach(chunksToScavenge,
		new ParallelOptions {MaxDegreeOfParallelism = _threads, CancellationToken = ct},
		(chunk, pls) => {
			var cache = scavengeCacheObjectPool.Get();
			try {
				ScavengeChunk(alwaysKeepScavenged, chunk, cache, ct);
			} finally {
				cache.Reset(); // reset thread local cache before next iteration.
				scavengeCacheObjectPool.Return(cache);
			}
		});
11

Thanks Alexey,

Could you please elaborate on this a bit more?

I can’t find any documents about the anti-affinity policy.

Thanks.

12

There’s plenty of documentation about pod scheduling restrictions. This article provides a good example of pod anti-affinity to prevent pods from being scheduled on the same node, you can find it in the “Pod Affinity and Anti-Affinity Demo” section.

13

Hi @noah_song

If you have a test database without sensitive data that scavenges slowly I wouldn’t mind taking a look at it. In the end it’s either something about your environment or data and it will help to figure out which

Thanks
Tim

14

I could share the test data as there is no such sensitive data. Could you please let me know you email address? I will send you the backup data file which would be around 6GB.

thanks.

15

That’s fantastic @noah_song : thank you so much

16

thanks @noah_song that’s great. it’ll likely be a bit smaller when zipped too. please send it (or a drop box link if its too big) to [email protected]

Thanks
Tim

17

Hi @noah_song thanks for the files. On my machine the first scavenge takes 1 minute 50 seconds.

[96480,11,14:39:55.480,DBG] SCAVENGING: Scavenge Completed. Total time taken: 00:01:50.8764960. Total space saved: 1064369808.
[96480,11,14:39:55.480,DBG] SCAVENGING: 0 KNOWN COLLISIONS
[96480,11,14:39:55.481,DBG] SCAVENGING: "Accumulation" took 00:00:13.6046614
[96480,11,14:39:55.481,DBG] SCAVENGING: "Calculation" took 00:00:00.6758377
[96480,11,14:39:55.481,DBG] SCAVENGING: "Chunk execution" took 00:01:24.3846235
[96480,11,14:39:55.481,DBG] SCAVENGING: "Chunk merging" took 00:00:06.1925417
[96480,11,14:39:55.482,DBG] SCAVENGING: "Cleaning" took 00:00:00.0015293
[96480,11,14:39:55.482,DBG] SCAVENGING: "Index execution" took 00:00:05.3003097

The second scavenge takes ~7 seconds (but there isn’t anything extra to scavenge so it ought to be quite fast)

[96480,23,14:41:39.823,DBG] SCAVENGING: Scavenge Completed. Total time taken: 00:00:06.5809018. Total space saved: 0.
[96480,23,14:41:39.823,DBG] SCAVENGING: 0 KNOWN COLLISIONS
[96480,23,14:41:39.823,DBG] SCAVENGING: "Accumulation" took 00:00:00.0075765
[96480,23,14:41:39.823,DBG] SCAVENGING: "Calculation" took 00:00:00.0545011
[96480,23,14:41:39.823,DBG] SCAVENGING: "Chunk execution" took 00:00:02.4564362
[96480,23,14:41:39.823,DBG] SCAVENGING: "Chunk merging" took 00:00:01.5528754
[96480,23,14:41:39.823,DBG] SCAVENGING: "Cleaning" took 00:00:00.0003759
[96480,23,14:41:39.823,DBG] SCAVENGING: "Index execution" took 00:00:01.9662945

So at least we can conclude that the slowness isn’t caused by your data.

It could be worth double checking if some resource somewhere is getting saturated (CPU, Disk IOPS, Disk Bandwidth, Burst credits for everything). Azure tracks disk iops and bandwith separately (you’re probably aware) so it’s possible to run out of one while the graph for the other still looks fine

Thanks
Tim

18

Just to add, it’s possible to set a threshold when you scavenge so that only the chunks with enough data to be worth scavenging actually get scavenged. this would reduce the work done by the chunk execution phase

https://developers.eventstore.com/server/v23.10/operations.html#threshold

(my timings above were with the default settings though, to be clear)

19

Thanks for your prompt reply and investigation, Tim.

Could you please share your ESDB server settings? I wonder if there is any misconfiguration in our server.
We’re using a cluster which consists of 4 nodes, 3 node and 1 readonly replica.

I will also double check the resources and get back to you.

I really appreciate your help.

Cheers.

20

hi @noah_song, sorry for the slow reply. i ran it with 23.10.1 and the default settings