Plotting extremely slow, CPU barely utilized

cipoint · January 23, 2024, 6:33am

As you can see from the logs down below, sector times are above 1h for 4 concurrent plots. With a single plot, sector times were ranging between 20m and 30m, basically same behavior.

I had no issues with an older release from January. After updating to latest release the farmer became extremely slow. The CPU load is basically below 5%. I tried default parameters as well as providing sector-downloading-concurrency etc. manually.
Internet connection is 1Gbps down / 50MBps up. Node is synced and working fine. The farmer is basically idling most of the time and only occasionally puts a few cores under load for short periods.

Edit: I tested jan-08, dec-22 and dec-11 releases. All with same results.
node execution:

bin/node \
--chain gemini-3g \
--blocks-pruning 256 \
--state-pruning archive \
--validator \
--no-private-ipv4 \
--base-path "/home/user/subspace/node_data" \
--name ...

farmer execution:

bin/farmer farm \
--reward-address ... \
--farming-thread-pool-size 32 \
--plotting-thread-pool-size 4 \
--sector-encoding-concurrency 4 \
--sector-downloading-concurrency 4 \
path=/media/user/NVME0/plot0,size=100GiB \
path=/media/user/NVME0/plot1,size=100GiB \
path=/media/user/NVME0/plot2,size=100GiB \
path=/media/user/NVME0/plot3,size=100GiB

node info:

2024-01-23T05:56:17.748602Z Subspace    
2024-01-23T05:56:17.748663Z ✌️  version 0.1.0-bd435100200    
2024-01-23T05:56:17.748679Z ❤️  by Subspace Labs <https://subspace.network>, 2021-2024    
2024-01-23T05:56:17.748680Z 📋 Chain specification: Subspace Gemini 3g    
2024-01-23T05:56:17.748681Z 🏷  Node name: ...    
2024-01-23T05:56:17.748681Z 👤 Role: AUTHORITY    
2024-01-23T05:56:17.748687Z 💾 Database: ParityDb at /home/user/subspace/node_data/chains/subspace_gemini_3g/paritydb/full    
2024-01-23T05:56:18.992779Z [Consensus] DSN instance configured. allow_non_global_addresses_in_dht=false peer_id=... protocol_version=/subspace/2/418040fc282f5e5ddd432c46d05297636f6f75ce68d66499ff4cbda69ccd180b
2024-01-23T05:56:18.993060Z [Consensus] local_peer_id=...
2024-01-23T05:56:18.993429Z [Consensus] Subspace networking initialized: Node ID is ...
2024-01-23T05:56:18.993625Z [Consensus] relay::consensus block server: starting
2024-01-23T05:56:18.993766Z [Consensus] DSN listening on /ip4/127.0.0.1/udp/30433/quic-v1/p2p/...
2024-01-23T05:56:18.993809Z [Consensus] 🏷  Local node identity is: ...    
2024-01-23T05:56:18.993914Z [Consensus] DSN listening on /ip4/192.168.0.21/udp/30433/quic-v1/p2p/...
2024-01-23T05:56:18.993941Z [Consensus] DSN listening on /ip4/127.0.0.1/tcp/30433/p2p/...
2024-01-23T05:56:18.993948Z [Consensus] DSN listening on /ip4/192.168.0.21/tcp/30433/p2p/...
2024-01-23T05:56:18.994550Z [Consensus] Resuming archiver from last archived block last_archived_block_number=1219965
2024-01-23T05:56:18.994573Z [Consensus] Archiving already produced blocks 1219966..=1221214
2024-01-23T05:56:19.032567Z [Consensus] 🧑‍🌾 Starting Subspace Authorship worker
2024-01-23T05:56:19.032671Z [Consensus] Metrics server started. endpoints=[127.0.0.1:9615]
2024-01-23T05:56:19.032675Z [Consensus] starting 2 workers
2024-01-23T05:56:19.032702Z [Consensus] Tokio runtime found; starting in existing Tokio runtime
2024-01-23T05:56:19.036997Z [Consensus] 💻 Operating system: linux    
2024-01-23T05:56:19.036999Z [Consensus] 💻 CPU architecture: x86_64    
2024-01-23T05:56:19.036999Z [Consensus] 💻 Target environment: gnu    
2024-01-23T05:56:19.037000Z [Consensus] 💻 CPU: AMD Ryzen 9 7950X 16-Core Processor    
2024-01-23T05:56:19.037001Z [Consensus] 💻 CPU cores: 16    
2024-01-23T05:56:19.037001Z [Consensus] 💻 Memory: 63459MB    
2024-01-23T05:56:19.037001Z [Consensus] 💻 Kernel: 6.1.69-060169-generic    
2024-01-23T05:56:19.037002Z [Consensus] 💻 Linux distribution: Ubuntu 22.04.3 LTS    
2024-01-23T05:56:19.037002Z [Consensus] 💻 Virtual machine: no    
2024-01-23T05:56:19.037018Z [Consensus] 📦 Highest known block at #1221314

farmer info:

2024-01-23T06:02:12.291275Z  INFO subspace_farmer::commands::farm: Connecting to node RPC url=ws://127.0.0.1:9944
2024-01-23T06:02:12.292868Z  INFO subspace_networking::constructor: DSN instance configured. allow_non_global_addresses_in_dht=false peer_id=... protocol_version=/subspace/2/418040fc282f5e5ddd432c46d05297636f6f75ce68d66499ff4cbda69ccd180b
2024-01-23T06:02:12.293137Z  INFO libp2p_swarm: local_peer_id=...
Single disk farm 0:
  ID: ...
  Genesis hash: 0x418040fc282f5e5ddd432c46d05297636f6f75ce68d66499ff4cbda69ccd180b
  Public key: ...
  Allocated space: 100.0 GiB (107.4 GB)
  Directory: /media/user/NVME0/plot0
Single disk farm 1:
  ID: ...
  Genesis hash: 0x418040fc282f5e5ddd432c46d05297636f6f75ce68d66499ff4cbda69ccd180b
  Public key: ...
  Allocated space: 100.0 GiB (107.4 GB)
  Directory: /media/user/NVME0/plot1
Single disk farm 2:
  ID: ...
  Genesis hash: 0x418040fc282f5e5ddd432c46d05297636f6f75ce68d66499ff4cbda69ccd180b
  Public key: ...
  Allocated space: 100.0 GiB (107.4 GB)
  Directory: /media/user/NVME0/plot2
Single disk farm 3:
  ID: ...
  Genesis hash: 0x418040fc282f5e5ddd432c46d05297636f6f75ce68d66499ff4cbda69ccd180b
  Public key: ...
  Allocated space: 100.0 GiB (107.4 GB)
  Directory: /media/user/NVME0/plot3

sector times:

2024-01-23T00:15:10.867204Z  INFO single_disk_farm{disk_farm_index=1}: subspace_farmer::single_disk_farm::plotting: Plotting sector (0.00% complete) sector_index=0
2024-01-23T00:15:10.868122Z  INFO single_disk_farm{disk_farm_index=0}: subspace_farmer::single_disk_farm::plotting: Plotting sector (45.00% complete) sector_index=45
2024-01-23T00:15:10.873861Z  INFO single_disk_farm{disk_farm_index=3}: subspace_farmer::single_disk_farm::plotting: Plotting sector (0.00% complete) sector_index=0
2024-01-23T00:15:10.873872Z  INFO single_disk_farm{disk_farm_index=2}: subspace_farmer::single_disk_farm::plotting: Plotting sector (0.00% complete) sector_index=0
2024-01-23T01:35:51.618569Z  INFO single_disk_farm{disk_farm_index=3}: subspace_farmer::single_disk_farm::plotting: Plotting sector (1.00% complete) sector_index=1
2024-01-23T01:35:52.399033Z  INFO single_disk_farm{disk_farm_index=1}: subspace_farmer::single_disk_farm::plotting: Plotting sector (1.00% complete) sector_index=1
2024-01-23T01:35:59.256122Z  INFO single_disk_farm{disk_farm_index=0}: subspace_farmer::single_disk_farm::plotting: Plotting sector (46.00% complete) sector_index=46
2024-01-23T01:36:11.434801Z  INFO single_disk_farm{disk_farm_index=2}: subspace_farmer::single_disk_farm::plotting: Plotting sector (1.00% complete) sector_index=1
2024-01-23T02:24:35.242309Z  INFO single_disk_farm{disk_farm_index=1}: subspace_farmer::single_disk_farm::plotting: Plotting sector (2.00% complete) sector_index=2
2024-01-23T02:24:43.223337Z  INFO single_disk_farm{disk_farm_index=3}: subspace_farmer::single_disk_farm::plotting: Plotting sector (2.00% complete) sector_index=2
2024-01-23T02:25:34.464033Z  INFO single_disk_farm{disk_farm_index=0}: subspace_farmer::single_disk_farm::plotting: Plotting sector (47.00% complete) sector_index=47
2024-01-23T02:26:18.449235Z  INFO single_disk_farm{disk_farm_index=2}: subspace_farmer::single_disk_farm::plotting: Plotting sector (2.00% complete) sector_index=2
2024-01-23T03:05:23.679406Z  INFO single_disk_farm{disk_farm_index=1}: subspace_farmer::single_disk_farm::plotting: Plotting sector (3.00% complete) sector_index=3
2024-01-23T03:10:10.338877Z  INFO single_disk_farm{disk_farm_index=3}: subspace_farmer::single_disk_farm::plotting: Plotting sector (3.00% complete) sector_index=3
2024-01-23T03:11:12.485921Z  INFO single_disk_farm{disk_farm_index=0}: subspace_farmer::single_disk_farm::plotting: Plotting sector (48.00% complete) sector_index=48
2024-01-23T03:11:17.581458Z  INFO single_disk_farm{disk_farm_index=2}: subspace_farmer::single_disk_farm::plotting: Plotting sector (3.00% complete) sector_index=3
2024-01-23T03:37:49.596620Z  INFO single_disk_farm{disk_farm_index=1}: subspace_farmer::single_disk_farm::plotting: Plotting sector (4.00% complete) sector_index=4
2024-01-23T04:02:20.172163Z  INFO single_disk_farm{disk_farm_index=0}: subspace_farmer::single_disk_farm::plotting: Plotting sector (49.00% complete) sector_index=49
2024-01-23T04:18:25.238906Z  INFO single_disk_farm{disk_farm_index=3}: subspace_farmer::single_disk_farm::plotting: Plotting sector (4.00% complete) sector_index=4
2024-01-23T04:30:14.081902Z  INFO single_disk_farm{disk_farm_index=2}: subspace_farmer::single_disk_farm::plotting: Plotting sector (4.00% complete) sector_index=4

Disk 0 is ahead of others because I started with single plot first.

nazar-pc · January 23, 2024, 1:15pm

The reason is most likely Farmer takes a long time to download pieces · Issue #2398 · subspace/subspace · GitHub, it just takes a really long time to download pieces.
This is compensated on large farms by local piece cache, but in your case many pieces will have to be downloaded from the network.

@shamil is looking into the root cause of this, subscribe to GitHub issue for updates.

cipoint · January 23, 2024, 7:58pm

Thank your for the reply. Indeed, that seems to be the case. I commented on that here: Farmer takes a long time to download pieces · Issue #2398 · subspace/subspace · GitHub

Topic		Replies	Views
Gemini-3h Plotting sector very very slow since Finished syncing piece cache to the latest history size Support farmer , plotting	6	80	April 15, 2024
Two farms slowed to a crawl after system reboots, now one won't plot and one wont win rewards Support	11	184	November 17, 2023
Plotting speed and synchronisation Support	5	506	June 13, 2022
Farming not working on gemini-3d Support	18	770	April 28, 2023
Farmer "Synchronizing Cache" never completes, plotting very very slow Support	8	327	April 15, 2024

Plotting extremely slow, CPU barely utilized

Related Topics