@contrast/perf - npm Package Compare versions

Comparing version 1.2.0 to 1.2.1

lib/index.js

@@ -23,2 +23,12 @@ /*
 
+// each instance map has metadata associated with the map itself.
+
+// this is the stats type
+const kStatsType = Symbol('stats-type');
+const kSimple = 'simple';
+const kStreaming = 'streaming';
+// this is how many times the map has been updated
+const kUpdateCount = Symbol('update-count');
+const kReportedCount = Symbol('reported-count');
+
 class Perf {
@@ -31,9 +41,15 @@ constructor(prefix, options = {}) {
     if (options.streaming) {
+      this.timings[kStatsType] = kStreaming;
       this.record = this.recordWithStats;
       this.getStats = (precision) => Perf.getStreamingStats(this.timings, precision);
     } else {
+      this.timings[kStatsType] = kSimple;
       this.record = this.recordSimple;
       this.getStats = (precision) => Perf.getStats(this.timings, precision);
     }
+    this.timings[kUpdateCount] = 0n;
+    this.timings[kReportedCount] = 0n;
 
+    this.writer = null;
+
     // for testing. i don't like this, but it's the only way to test the
@@ -52,7 +68,30 @@ // record functions and resulting data.
 
-  // findings across all instances of Perf are kept here. this seems better
-  // than keeping them in a global.
+  // interval setting
+  static interval_ms = +process.env.CSI_PERF_INTERVAL || 60_000;
+
+  // findings across all instances of Perf are kept here. each instance has it's own
+  // map of timings stored here.
+  //
+  // this seems better than keeping them in a global.
   static all = new Map();
 
+  // place for intermediate marks.
+  static marks = new Map();
 
+  // our interval timer
+  static interval = null;
+  static intervalCounter = 0;
+
+  static symbols = {
+    kStatsType,
+    kSimple,
+    kStreaming,
+    kUpdateCount,
+    kReportedCount,
+  };
+
+  // global counters
+  static requestCount = 0;
+
+
   /**
@@ -86,7 +125,88 @@ * This exists primarily for testing. It collects the timings from an instance
   /**
+   * This is used to collect the stats from all instances and replace them with
+   * empty maps. It is invoked on the 'listening' event to separate startup
+   * stats from runtime stats.
+   *
+   * N.B. For a given markPrefix, this will only work once for streaming stats.
+   * If it is called multiple times with the same markPrefix, the marked
+   * streaming stats will not be updated because they cannot be aggregated with
+   * the new streaming stats.
+   *
+   * So, If the server only listens once, this works fine with both streaming and
+   * non-streaming stats, but if the server calls listen multiple times, only
+   * non-streaming stats will be updated for the markPrefix.
+   */
+  static mark(markPrefix) {
+    let markEntries = Perf.marks.get(markPrefix);
+    if (!markEntries) {
+      markEntries = new Map();
+      Perf.marks.set(markPrefix, markEntries);
+    }
+
+    // there is a mark. the difference is that streaming instances are only
+    // captured the first time a mark is set. if the mark is set again, the
+    // streaming stats are reset, but the already captured mark is not
+    // overwritten.
+    //
+    // why is this? the thinking is that the window between multiple
+    // listening events is short enough that it's not worth the complexity
+    // to capture multiple versions of a mark. if it is, we can start
+    // capturing versions. yuck.
+
+    // iterate through the existing "all" entries and merge them into the mark
+    // if they are not streaming.
+    for (const [prefix, map] of Perf.all.entries()) {
+      if (map.size === 0) {
+        continue;
+      }
+
+      // if this "all" entry doesn't exist in the mark, copy it.
+      if (!markEntries.has(prefix)) {
+        const copiedMap = new Map(map);
+        copiedMap[kStatsType] = map[kStatsType];
+        copiedMap[kUpdateCount] = map[kUpdateCount];
+        copiedMap[kReportedCount] = map[kReportedCount];
+
+        markEntries.set(prefix, copiedMap);
+        map.clear();
+        continue;
+      }
+
+      // this "all" entry exists in the mark. don't merge streaming stats, but
+      // merge simple stats. clear both. the point of clearing is to remove
+      // the impact of startup code from request-handling.
+      if (map[kStatsType] === kSimple) {
+        for (const [k, v] of map.entries()) {
+          let existing = markEntries.get(prefix).get(k);
+          // it's possible that a new stat appeared.
+          if (!existing) {
+            existing = new Map([[k, [0, 0n]]]);
+            markEntries.set(prefix, existing);
+          }
+          existing[0] += v[0];
+          existing[1] += v[1];
+        }
+      } else if (map[kStatsType] === kStreaming) {
+        // should data for the second mark replace the first?
+        continue;
+        // they cannot be merged, so just copy the map.
+        // const copiedMap = new Map(map);
+        // copiedMap[kStatsType] = map[kStatsType];
+        // copiedMap[kUpdateCount] = map[kUpdateCount];
+        // copiedMap[kReportedCount] = map[kReportedCount];
+
+        // markEntries.set(prefix, copiedMap);
+      } else {
+        throw new Error(`invalid stats type: ${map[kStatsType]}`);
+      }
+
+      map.clear();
+    }
+  }
+
+  /**
    * This is a bit of a misnomer; it converts nanoseconds to microseconds and
    * calculates the mean. It returns a new map with the same keys and an object
    * with n, totalMicros, and mean. There are not individual observations so
-   * standard deviation is not calculated. See `record()` - it's possible to
-   * calculate mean and stddev on the fly if it's important.
+   * standard deviation is not calculated.
    *
@@ -110,2 +230,14 @@ * @param {Map} map - the map to calculate stats for
 
+  /**
+   * This is also a bit of a misnomer; it just formats the streaming stats
+   * and returns them in a new map. They've already been calculated by the
+   * RunningStats class.
+   *
+   * The logic is all part of the RunningStats class.
+   *
+   * @param {Map} map - the map to calculate stats for
+   * @param {number=2} precision - the number of decimal places to round to
+   * @returns {Map} - a new map with the same keys and the object returned by
+   * getStats().
+   */
   static getStreamingStats(map, precision = 2) {
@@ -121,3 +253,58 @@ const stats = new Map();
 
+  static getStatsType(map) {
+    return map[kStatsType];
+  }
+
   /**
+   * Sets up the interval timer to log perf data to a file.
+   */
+  static setInterval(options = {}) {
+    if (!Perf.isEnabled) {
+      return;
+    }
+
+    const {
+      name = 'agent-perf.jsonl',
+      interval = Perf.interval_ms || 60_000,
+      precision = 2,
+    } = options;
+
+    if (!this.writer) {
+      const Writer = require('./writer');
+      this.writer = new Writer(name);
+    }
+
+    Perf.interval = setInterval(() => {
+      Perf.intervalCounter += 1;
+
+      // if mark entries are present, log them for the first 5 intervals.
+      if (Perf.intervalCounter < 5 && Perf.marks.size !== 0) {
+        // log stats from the "listening" mark (only type of mark now).
+        for (const [markPrefix, markEntries] of Perf.marks.entries()) {
+          this.writer.writeAllMap(markEntries, markPrefix, precision);
+        }
+        // if requests have started, clear the marks.
+        if (Perf.requestCount > 0) {
+          Perf.marks.clear();
+        }
+      }
+
+      // nothing to log. it's possible to miss some timer-driven activity, so
+      // log every 5 intervals anyway.
+      if (Perf.intervalCounter % 5 !== 0) {
+        return;
+      }
+
+      // writeAllMap() is async, but we can't await because we're in setInterval
+      // callback. the key here is that the interval need to be long enough
+      // that any async operations will complete before the next interval.
+      // given that the interval is 60 seconds (and can't be user configured),
+      // this should be fine.
+      this.writer.writeAllMap(Perf.all, 'not-mark', precision);
+    }, interval);
+
+    this.interval.unref();
+  }
+
+  /**
    * This wraps init functions and the install function if present on the
@@ -219,3 +406,3 @@ * result init() returns. It is designed to be used be agentify.
     return pino;
-  };
+  }
 
@@ -299,2 +486,4 @@ /**
 
+    this.timings[kUpdateCount] += 1n;
+
     return deltaT;
@@ -319,2 +508,4 @@ }
 
+    this.timings[kUpdateCount] += 1n;
+
     return deltaT;
@@ -328,2 +519,5 @@ }
    *
+   * Not currently used because the "excluded" time can be derived from two raw
+   * times.
+   *
    * @param {string} tag - the tag to record
@@ -335,3 +529,3 @@ * @param {bigint} start - the start time
   recordExcluding(tag, start, excludeT) {
-    let deltaT = this.hrtime.bigint() - start - excludeT;
+    const deltaT = this.hrtime.bigint() - start - excludeT;
     let existing = this.timings.get(tag);
@@ -354,2 +548,6 @@ if (!existing) {
  * https://nestedsoftware.com/2018/03/27/calculating-standard-deviation-on-streaming-data-253l.23919.html
+ *
+ * Note: RunningStats keeps values in microseconds so that overflow is less
+ * likely. It is different than the way simpleRecord() works, which only
+ * converts to microseconds when stats are requested.
  */
@@ -380,2 +578,3 @@ class RunningStats {
     newValue = Number(newValue);
+
     const meanDifferential = (newValue - this.mean) / this.n;
@@ -382,0 +581,0 @@

lib/index.test.js

@@ -7,3 +7,2 @@ 'use strict';
 
-
 describe('perf', function () {
@@ -232,3 +231,3 @@ describe('Perf class', function () {
     afterEach(function() {
-      console.log(Perf.all);
+      //console.log(Perf.all);
     });
@@ -312,2 +311,130 @@
   });
+
+  describe('test prototype', function() {
+    const instances = [];
+    const values = {
+      'instance-0': [10, 20, 30],
+      'instance-1': [100, 200, 300],
+      'instance-2': [1000, 2000, 3000],
+      'streaming': [10000, 20000, 30000],
+    };
+    let firstMark;
+    before(async function() {
+      Perf.all.clear();
+      const prefixes = Object.keys(values);
+      for (let i = 0; i < 4; i++) {
+        const prefix = prefixes[i];
+        const options = {
+          streaming: prefix === 'streaming',
+          hrtime: () => BigInt(values[prefix].shift())
+        };
+        instances.push(new Perf(prefix, options));
+        for (let j = 0; j < 3; j++) {
+          instances[i].record('test', 0n);
+        }
+      }
+    });
+
+    it('dumps some stuff', function() {
+      // make a bunch of perf instances
+      const i0 = instances[0].timings;
+      const i1 = instances[1].timings;
+      const i2 = instances[2].timings;
+      const i3 = instances[3].timings;
+
+      expect(i0).deep.equal(new Map([['test', [3, 60n]]]));
+      expect(i1).deep.equal(new Map([['test', [3, 600n]]]));
+      expect(i2).deep.equal(new Map([['test', [3, 6000n]]]));
+      // maybe Perf should expose RunningStats?
+      expect(i3).instanceOf(Map);
+      expect(i3.size).equal(1);
+      const i3stats = i3.get('test');
+      expect(i3stats).property('n', 3);
+      expect(i3stats).property('totalMicros', 60n); // it's been converted to microseconds.
+
+      Perf.mark('listening');
+
+      expect(Perf.marks.get('listening')).instanceOf(Map);
+      const mark0 = Perf.marks.get('listening').get('instance-0');
+      const mark1 = Perf.marks.get('listening').get('instance-1');
+      const mark2 = Perf.marks.get('listening').get('instance-2');
+      const mark3 = Perf.marks.get('listening').get('streaming');
+
+      expect(mark0).deep.equal(new Map([['test', [3, 60n]]]));
+      expect(mark1).deep.equal(new Map([['test', [3, 600n]]]));
+      expect(mark2).deep.equal(new Map([['test', [3, 6000n]]]));
+
+      const s3 = mark3.get('test');
+      expect(s3).property('n', 3);
+      expect(s3).property('totalMicros', 60n);
+
+      /* eslint-disable */
+      expect(i0).instanceOf(Map).property('size', 0);
+      expect(i1).instanceOf(Map).property('size', 0);
+      expect(i2).instanceOf(Map).property('size', 0);
+      expect(i3).instanceOf(Map).property('size', 0);
+      /* eslint-enable */
+
+    });
+
+    it('gets the same answer for the streaming stats', async function() {
+      // duplicate the existing listening stats
+      firstMark = new Map(Perf.marks.get('listening'));
+      const firstMarkMaps = {};
+      for (const [prefix, data] of firstMark) {
+        firstMarkMaps[prefix] = new Map(data);
+      }
+
+      // add two more perf measurements
+      const values = {
+        'instance-0': [40, 50],
+        'instance-1': [400, 500],
+        'instance-2': [4000, 5000],
+        'streaming': [40000, 50000],
+      };
+      const prefixes = Object.keys(values);
+      for (let i = 0; i < 4; i++) {
+        const prefix = prefixes[i];
+        instances[i].hrtime = { bigint: () => BigInt(values[prefix].shift()) };
+        for (let j = 0; j < 2; j++) {
+          instances[i].record('test', 0n);
+        }
+      }
+
+      expect(Perf.marks.get('listening')).instanceOf(Map);
+      const all0 = Perf.all.get('instance-0');
+      const all1 = Perf.all.get('instance-1');
+      const all2 = Perf.all.get('instance-2');
+      const all3 = Perf.all.get('streaming');
+
+      expect(all0).deep.equal(new Map([['test', [2, 90n]]]));
+      expect(all1).deep.equal(new Map([['test', [2, 900n]]]));
+      expect(all2).deep.equal(new Map([['test', [2, 9000n]]]));
+
+      let s3 = all3.get('test');
+      expect(s3).property('n', 2);
+      expect(s3).property('totalMicros', 90n);
+
+      // ask for another mark of the same prefix. it should merge non-streaming
+      // and *not* replace streaming stats.
+      Perf.mark('listening');
+
+      /* eslint-disable */
+      expect(Perf.marks.get('listening')).instanceOf(Map);
+      const mark0 = Perf.marks.get('listening').get('instance-0');
+      const mark1 = Perf.marks.get('listening').get('instance-1');
+      const mark2 = Perf.marks.get('listening').get('instance-2');
+      const mark3 = Perf.marks.get('listening').get('streaming');
+      /* eslint-enable */
+
+      // simple stats are aggregated
+      expect(mark0).deep.equal(new Map([['test', [5, 150n]]]));
+      expect(mark1).deep.equal(new Map([['test', [5, 1500n]]]));
+      expect(mark2).deep.equal(new Map([['test', [5, 15000n]]]));
+      // streaming stats don't change
+      s3 = mark3.get('test');
+      expect(s3).property('n', 3);
+      expect(s3).property('totalMicros', 60n);
+    });
+  });
 });

lib/tsconfig.json

 {
+  "extends": "@tsconfig/node16/tsconfig.json",
   "compilerOptions": {
@@ -15,7 +16,6 @@ // Tells TypeScript to read JS files, as
     // next to the .js files
-    //"outDir": "dist",
+    "outDir": "../types",
     // go to js file when using IDE functions like
     // "Go to Definition" in VSCode
-    "declarationMap": true,
-    "outDir": "../types",
+    "declarationMap": true
   },
@@ -27,7 +27,3 @@ "references": [
   ],
-  "exclude": [
-    "../types",
-    "**/*.spec.*",
-    "**/*.test.*"
-  ]
+  "exclude": ["../types", "**/*.spec.*", "**/*.test.*"]
 }

package.json

 {
   "name": "@contrast/perf",
-  "version": "1.2.0",
+  "version": "1.2.1",
   "description": "Performance measurement",
@@ -21,4 +21,4 @@ "license": "SEE LICENSE IN LICENSE",
   "dependencies": {
-    "@contrast/logger": "1.12.0"
+    "sonic-boom": "^4.1.0"
   }
 }

New alerts

Environment variable access

Supply chain risk

Package accesses environment variables, which may be a sign of credential stuffing or data theft.

Found 1 instance in 1 package

Fixed alerts

No README

Quality

Package does not have a README. This may indicate a failed publish or a low quality package.

Found 1 instance in 1 package

Improved metrics

Total package byte prevSize

42866

increased by73.29%

Number of package files

7

increased by40%

Lines of code

1069

increased by64.71%

Number of medium quality alerts

0

decreased by-100%

Number of lines in readme file

28

increased byInfinity%

Worsened metrics

Number of low supply chain risk alerts

3

increased by50%

Dependency changes

• + Addedsonic-boom@^4.1.0

• + Addedsonic-boom@4.2.0(transitive)

• - Removed@contrast/logger@1.12.0

• - Removed@contrast/common@1.26.0(transitive)

• - Removed@contrast/config@1.34.0(transitive)

• - Removed@contrast/logger@1.12.0(transitive)

• - Removedabort-controller@3.0.0(transitive)

• - Removedbase64-js@1.5.1(transitive)

• - Removedbuffer@6.0.3(transitive)

• - Removedevent-target-shim@5.0.1(transitive)

• - Removedevents@3.3.0(transitive)

• - Removedfast-redact@3.5.0(transitive)

• - Removedieee754@1.2.1(transitive)

• - Removedon-exit-leak-free@2.1.2(transitive)

• - Removedpino@8.21.0(transitive)

• - Removedpino-abstract-transport@1.2.0(transitive)

• - Removedpino-std-serializers@6.2.2(transitive)

• - Removedprocess@0.11.10(transitive)

• - Removedprocess-warning@3.0.0(transitive)

• - Removedquick-format-unescaped@4.0.4(transitive)

• - Removedreadable-stream@4.7.0(transitive)

• - Removedreal-require@0.2.0(transitive)

• - Removedsafe-buffer@5.2.1(transitive)

• - Removedsafe-stable-stringify@2.5.0(transitive)

• - Removedsonic-boom@3.8.1(transitive)

• - Removedsplit2@4.2.0(transitive)

• - Removedstring_decoder@1.3.0(transitive)

• - Removedthread-stream@2.7.0(transitive)

• - Removedyaml@2.7.0(transitive)