Merge branch 'better_cpu_adjustement' into '1.6'

[enh] Better CPU% auto adjustment

See merge request !1218

app/ProcessCpuProfiler.ts

+const SAMPLING_PERIOD = 150 // milliseconds
+const MAX_SAMPLES_DISTANCE = 20 * 1000000 // seconds
+
+function getMicrosecondsTime() {
+  const [ seconds, nanoseconds ] = process.hrtime()
+  return seconds * 1000000 + nanoseconds / 1000
+}
+
+interface CpuUsage {
+  user: number
+  system:number
+}
+
+interface CpuUsageAt {
+  usage:number
+  at:number // microseconds timestamp
+  elapsed:number // microseconds elapsed for this result
+}
+
+export class ProcessCpuProfiler {
+
+  private cumulatedUsage: CpuUsage
+  private startedAt:number // microseconds timestamp
+  private samples:CpuUsageAt[] = []
+
+  constructor(samplingPeriod = SAMPLING_PERIOD) {
+    // Initial state
+    const start = getMicrosecondsTime()
+    this.startedAt = start
+    this.cumulatedUsage = process.cpuUsage()
+    this.samples.push({ usage: 0, at: start, elapsed: 1 })
+    // Periodic sample
+    setInterval(() => {
+      const newSampleAt = getMicrosecondsTime()
+      const newUsage:CpuUsage = process.cpuUsage()
+      const elapsed = newSampleAt - this.lastSampleAt
+      const userDiff = newUsage.user - this.cumulatedUsage.user
+      const usagePercent = userDiff / elapsed // The percent of time consumed by the process since last sample
+      this.samples.push({ usage: usagePercent, at: newSampleAt, elapsed })
+      while(this.samplesDistance > MAX_SAMPLES_DISTANCE) {
+        this.samples.shift()
+      }
+      this.cumulatedUsage = newUsage
+      // console.log('Time elapsed: %s microseconds, = %s %CPU', elapsed, (usagePercent*100).toFixed(2))
+    }, samplingPeriod)
+  }
+
+  private get lastSampleAt() {
+    return this.samples[this.samples.length - 1].at
+  }
+
+  private get samplesDistance() {
+    return this.samples[this.samples.length - 1].at - this.samples[0].at
+  }
+
+  cpuUsageOverLastMilliseconds(elapsedMilliseconds:number) {
+    return this.cpuUsageOverLastX(elapsedMilliseconds * 1000)
+  }
+
+  private cpuUsageOverLastX(nbMicrosecondsElapsed:number) {
+    return this.getSamplesResult(getMicrosecondsTime() - nbMicrosecondsElapsed)
+  }
+
+  private getSamplesResult(minTimestamp:number) {
+    const matchingSamples = this.samples.filter(s => s.at >= minTimestamp - SAMPLING_PERIOD * 1000)
+    const cumulativeElapsed = matchingSamples.reduce((sum, s) => sum + s.elapsed, 0)
+    return matchingSamples.reduce((cumulated, percent) => {
+      const weight = percent.elapsed / cumulativeElapsed
+      return cumulated + percent.usage * weight
+    }, 0)
+  }
+}
\ No newline at end of file

app/modules/prover/lib/blockProver.ts

@@ -44,6 +44,9 @@ export class WorkerFarm {
     })
   }
 
+  get nbWorkers() {
+    return this.theEngine.getNbWorkers()
+  }
 
   changeCPU(cpu:any) {
     return this.theEngine.setConf({ cpu })
@@ -175,7 +178,6 @@ export class BlockProver {
       const start = Date.now();
       let result = await powFarm.askNewProof({
         newPoW: {
-          turnDuration: os.arch().match(/arm/) ? CommonConstants.POW_TURN_DURATION_ARM : CommonConstants.POW_TURN_DURATION_PC,
           conf: {
             cpu: this.conf.cpu,
             prefix: this.conf.prefix,
@@ -194,10 +196,10 @@ export class BlockProver {
         throw 'Proof-of-work computation canceled because block received';
       } else {
         const proof = result.block;
-        const testsCount = result.testsCount;
+        const testsCount = result.testsCount * powFarm.nbWorkers
         const duration = (Date.now() - start);
-        const testsPerSecond = (testsCount / (duration / 1000)).toFixed(2);
-        this.logger.info('Done: #%s, %s in %ss (%s tests, ~%s tests/s)', block.number, proof.hash, (duration / 1000).toFixed(2), testsCount, testsPerSecond);
+        const testsPerSecond = testsCount / (duration / 1000)
+        this.logger.info('Done: #%s, %s in %ss (~%s tests, ~%s tests/s, using %s cores, CPU %s%)', block.number, proof.hash, (duration / 1000).toFixed(2), testsCount, testsPerSecond.toFixed(2), powFarm.nbWorkers, Math.floor(100*this.conf.cpu))
         this.logger.info('FOUND proof-of-work with %s leading zeros followed by [0-' + highMark + ']!', nbZeros);
         return BlockDTO.fromJSONObject(proof)
       }

app/modules/prover/lib/engine.ts

@@ -25,6 +25,10 @@ export class PowEngine {
     this.id = this.cluster.clusterId
   }
 
+  getNbWorkers() {
+    return this.cluster.nbWorkers
+  }
+
   forceInit() {
     return this.cluster.initCluster()
   }
@@ -35,9 +39,6 @@ export class PowEngine {
       await this.cluster.cancelWork()
     }
 
-    if (os.arch().match(/arm/)) {
-      stuff.newPoW.conf.cpu /= 2; // Don't know exactly why is ARM so much saturated by PoW, so let's divide by 2
-    }
     return await this.cluster.proveByWorkers(stuff)
   }
 
@@ -46,9 +47,6 @@ export class PowEngine {
   }
 
   setConf(value:any) {
-    if (os.arch().match(/arm/) && value.cpu !== undefined) {
-      value.cpu /= 2; // Don't know exactly why is ARM so much saturated by PoW, so let's divide by 2
-    }
     return this.cluster.changeConf(value)
   }
 

app/modules/prover/lib/powCluster.ts

@@ -195,7 +195,6 @@ export class Master {
             highMark: stuff.newPoW.highMark,
             pair: _.clone(stuff.newPoW.pair),
             forcedTime: stuff.newPoW.forcedTime,
-            turnDuration: stuff.newPoW.turnDuration,
             conf: {
               medianTimeBlocks: stuff.newPoW.conf.medianTimeBlocks,
               avgGenTime: stuff.newPoW.conf.avgGenTime,

app/modules/prover/lib/proof.ts

@@ -6,15 +6,11 @@ import {Constants} from "./constants"
 import {KeyGen} from "../../../lib/common-libs/crypto/keyring"
 import {dos2unix} from "../../../lib/common-libs/dos2unix"
 import {rawer} from "../../../lib/common-libs/index"
+import {ProcessCpuProfiler} from "../../../ProcessCpuProfiler"
 
 const moment = require('moment');
 const querablep = require('querablep');
 
-const PAUSES_PER_TURN = 5;
-
-// This value can be changed
-let TURN_DURATION_IN_MILLISEC = 100;
-
 let computing = querablep(Promise.resolve(null));
 let askedStop = false;
 
@@ -90,7 +86,6 @@ function beginNewProofOfWork(stuff:any) {
       prefix *= 100 * Constants.NONCE_RANGE
     }
     const highMark = stuff.highMark;
-    const turnDuration = stuff.turnDuration || TURN_DURATION_IN_MILLISEC
     let sigFunc = null;
     if (signatureFunc && lastSecret === pair.sec) {
       sigFunc = signatureFunc;
@@ -108,13 +103,17 @@ function beginNewProofOfWork(stuff:any) {
 
     let testsCount = 0;
     let found = false;
-    let score = 0;
     let turn = 0;
+    const profiler = new ProcessCpuProfiler(100)
+    let cpuUsage = profiler.cpuUsageOverLastMilliseconds(1)
+    // We limit the number of tests according to CPU usage
+    let testsPerRound = 1
+    let turnDuration = 20 // We initially goes quickly to the max speed = 50 reevaluations per second (1000 / 20)
 
     while (!found && !askedStop) {
 
       /*****************
-       * A TURN
+       * A TURN ~ 100ms
        ****************/
 
       await Promise.race([
@@ -125,26 +124,9 @@ function beginNewProofOfWork(stuff:any) {
         // II. Process the turn's PoW
         (async () => {
 
-          /*****************
-           * A TURN OF POW ~= 100ms by default
-           * --------------------
-           *
-           * The concept of "turn" is required to limit the CPU usage.
-           * We need a time reference to have the speed = nb tests / period of time.
-           * Here we have:
-           *
-           *   - speed = testsCount / turn
-           *
-           * We have taken 1 turn = 100ms to control the CPU usage after 100ms of PoW. This means that during the
-           * very first 100ms of the PoW, CPU usage = 100%. Then it becomes controlled to the %CPU set.
-           ****************/
-
             // Prove
           let i = 0;
           const thisTurn = turn;
-          const pausePeriod = score ? score / PAUSES_PER_TURN : 10; // number of pauses per turn
-          // We limit the number of tests according to CPU usage
-          const testsPerRound = score ? Math.floor(score * currentCPU) : 1000 * 1000 * 1000
 
           // Time is updated regularly during the proof
           block.time = getBlockTime(block, conf, forcedTime)
@@ -196,7 +178,7 @@ function beginNewProofOfWork(stuff:any) {
             if (!found && !askedStop) {
               i++;
               testsCount++;
-              if (i % pausePeriod === 0) {
+              if (i % testsPerRound === 0) {
                 await countDown(0); // Very low pause, just the time to process eventual end of the turn
               }
             }
@@ -208,12 +190,24 @@ function beginNewProofOfWork(stuff:any) {
           if (!found) {
 
             // CPU speed recording
-            if (turn > 0 && !score) {
-              score = testsCount;
+            if (turn > 0) {
+              const oldTestsPerRound = testsPerRound
+              cpuUsage = profiler.cpuUsageOverLastMilliseconds(turnDuration)
+              if (cpuUsage > currentCPU + 0.005 || cpuUsage < currentCPU - 0.005) {
+                let powVariationFactor
+                // powVariationFactor = currentCPU / (cpuUsage || 0.01) / 5 // divide by 2 to avoid extreme responses
+                if (currentCPU > cpuUsage) {
+                  powVariationFactor = 1.01
+                  testsPerRound = Math.max(1, Math.ceil(testsPerRound * powVariationFactor))
+                } else {
+                  powVariationFactor = 0.99
+                  testsPerRound = Math.max(1, Math.floor(testsPerRound * powVariationFactor))
+                }
+              }
             }
 
             /*****************
-             * UNLOAD CPU CHARGE
+             * UNLOAD CPU CHARGE FOR THIS TURN
              ****************/
             // We wait for a maximum time of `turnDuration`.
             // This will trigger the end of the turn by the concurrent race I. During that time, the proof.js script
@@ -226,6 +220,9 @@ function beginNewProofOfWork(stuff:any) {
 
       // Next turn
       turn++
+
+      turnDuration += 1
+      turnDuration = Math.min(turnDuration, 1000) // Max 1 second per turn
     }
 
     /*****************