Commit a5fa15c5 authored by Brian Hackett's avatar Brian Hackett
Browse files

Bug 1556858 - Track memory/timing statistics in control logic, r=loganfsmyth. 

--HG--
extra : rebase_source : a1e5f25258da738ba9dcf3d1814e51c9b2097fd0
parent affccc38

devtools/server/actors/replay/control.js

+126 −6
Original line number Diff line number Diff line
@@ -111,6 +111,9 @@ function ChildProcess(id, recording) { 
  // The last point we paused at.

  this.lastPausePoint = null;



  // Last reported memory usage for this child.

  this.lastMemoryUsage = null;



  // Manifests which this child needs to send asynchronously.

  this.asyncManifests = [];
@@ -168,19 +171,25 @@ ChildProcess.prototype = { 
    this.paused = false;

    this.manifest = manifest;



    dumpv(`SendManifest #${this.id} ${JSON.stringify(manifest.contents)}`);

    dumpv(`SendManifest #${this.id} ${stringify(manifest.contents)}`);

    RecordReplayControl.sendManifest(this.id, manifest.contents);

  },



  // Called when the child's current manifest finishes.

  manifestFinished(response) {

    assert(!this.paused);

    if (response && response.point) {

    if (response) {

      if (response.point) {

        this.lastPausePoint = response.point;

      }

      if (response.memoryUsage) {

        this.lastMemoryUsage = response.memoryUsage;

      }

    }

    this.paused = true;

    this.manifest.onFinished(response);

    this.manifest = null;

    maybeDumpStatistics();

  },



  // Block until this child is paused. If maybeCreateCheckpoint is specified
@@ -346,6 +355,15 @@ function CheckpointInfo() { 
  // If the checkpoint is saved, the replaying child responsible for saving it

  // and scanning the region up to the next saved checkpoint.

  this.owner = null;



  // If the checkpoint is saved, the time it was assigned an owner.

  this.assignTime = null;



  // If the checkpoint is saved and scanned, the time it finished being scanned.

  this.scanTime = null;



  // If the checkpoint is saved and scanned, the duration of the scan.

  this.scanDuration = null;

}



function getCheckpointInfo(id) {
@@ -364,6 +382,16 @@ function timeSinceCheckpoint(id) { 
  return time;

}



// How much execution time is captured by a saved checkpoint.

function timeForSavedCheckpoint(id) {

  const next = nextSavedCheckpoint(id);

  let time = 0;

  for (let i = id; i < next; i++) {

    time += gCheckpoints[i].duration;

  }

  return time;

}



// The checkpoint up to which the recording runs.

let gLastFlushCheckpoint = InvalidCheckpointId;
@@ -377,6 +405,7 @@ function addSavedCheckpoint(checkpoint) { 


  const owner = pickReplayingChild();

  getCheckpointInfo(checkpoint).owner = owner;

  getCheckpointInfo(checkpoint).assignTime = Date.now();

  owner.addSavedCheckpoint(checkpoint);

}
@@ -542,7 +571,14 @@ function scanRecording(checkpoint) { 
          needSaveCheckpoints: child.flushNeedSaveCheckpoints(),

        };

      },

      onFinished: child => child.scannedCheckpoints.add(checkpoint),

      onFinished(child, { duration }) {

        child.scannedCheckpoints.add(checkpoint);

        const info = getCheckpointInfo(checkpoint);

        if (!info.scanTime) {

          info.scanTime = Date.now();

          info.scanDuration = duration;

        }

      },

    },

    checkpointExecutionPoint(checkpoint)

  );
@@ -1139,7 +1175,7 @@ function Initialize(recordingChildId) { 
// eslint-disable-next-line no-unused-vars

function ManifestFinished(id, response) {

  try {

    dumpv(`ManifestFinished #${id} ${JSON.stringify(response)}`);

    dumpv(`ManifestFinished #${id} ${stringify(response)}`);

    lookupChild(id).manifestFinished(response);

  } catch (e) {

    dump(`ERROR: ManifestFinished threw exception: ${e} ${e.stack}\n`);
@@ -1314,6 +1350,75 @@ const gControl = { 
  },

};



///////////////////////////////////////////////////////////////////////////////

// Statistics

///////////////////////////////////////////////////////////////////////////////



let lastDumpTime = Date.now();



function maybeDumpStatistics() {

  const now = Date.now();

  if (now - lastDumpTime < 5000) {

    return;

  }

  lastDumpTime = now;



  let delayTotal = 0;

  let unscannedTotal = 0;

  let timeTotal = 0;

  let scanDurationTotal = 0;



  forSavedCheckpointsInRange(

    FirstCheckpointId,

    gLastFlushCheckpoint,

    checkpoint => {

      const checkpointTime = timeForSavedCheckpoint(checkpoint);

      const info = getCheckpointInfo(checkpoint);



      timeTotal += checkpointTime;

      if (info.scanTime) {

        delayTotal += checkpointTime * (info.scanTime - info.assignTime);

        scanDurationTotal += info.scanDuration;

      } else {

        unscannedTotal += checkpointTime;

      }

    }

  );



  const memoryUsage = [];

  let totalSaved = 0;



  for (const child of gReplayingChildren) {

    if (!child) {

      continue;

    }

    totalSaved += child.savedCheckpoints.size;

    if (!child.lastMemoryUsage) {

      continue;

    }

    for (const [name, value] of Object.entries(child.lastMemoryUsage)) {

      if (!memoryUsage[name]) {

        memoryUsage[name] = 0;

      }

      memoryUsage[name] += value;

    }

  }



  const delay = delayTotal / timeTotal;

  const overhead = scanDurationTotal / (timeTotal - unscannedTotal);



  dumpv(`Statistics:`);

  dumpv(`Total recording time: ${timeTotal}`);

  dumpv(`Unscanned fraction: ${unscannedTotal / timeTotal}`);

  dumpv(`Average scan delay: ${delay}`);

  dumpv(`Average scanning overhead: ${overhead}`);



  dumpv(`Saved checkpoints: ${totalSaved}`);

  for (const [name, value] of Object.entries(memoryUsage)) {

    dumpv(`Memory ${name}: ${value}`);

  }

}



///////////////////////////////////////////////////////////////////////////////

// Utilities

///////////////////////////////////////////////////////////////////////////////
@@ -1324,8 +1429,15 @@ function ConnectDebugger(dbg) { 
  dbg._control = gControl;

}



const startTime = Date.now();



// eslint-disable-next-line no-unused-vars

function currentTime() {

  return (((Date.now() - startTime) / 10) | 0) / 100;

}



function dumpv(str) {

  //dump(`[ReplayControl] ${str}\n`);

  //dump(`[ReplayControl ${currentTime()}] ${str}\n`);

}



function assert(v) {
@@ -1340,6 +1452,14 @@ function ThrowError(msg) { 
  throw error;

}



function stringify(object) {

  const str = JSON.stringify(object);

  if (str && str.length >= 4096) {

    return `${str.substr(0, 4096)} TRIMMED ${str.length}`;

  }

  return str;

}



// eslint-disable-next-line no-unused-vars

var EXPORTED_SYMBOLS = [

  "Initialize",

devtools/server/actors/replay/debugger.js

+9 −3
Original line number Diff line number Diff line
@@ -123,9 +123,7 @@ ReplayDebugger.prototype = { 
  },



  _processResponse(request, response, divergeResponse) {

    dumpv(

      `SendRequest: ${JSON.stringify(request)} -> ${JSON.stringify(response)}`

    );

    dumpv(`SendRequest: ${stringify(request)} -> ${stringify(response)}`);

    if (response.exception) {

      ThrowError(response.exception);

    }
@@ -1372,4 +1370,12 @@ function isNonNullObject(obj) { 
  return obj && (typeof obj == "object" || typeof obj == "function");

}



function stringify(object) {

  const str = JSON.stringify(object);

  if (str.length >= 4096) {

    return `${str.substr(0, 4096)} TRIMMED ${str.length}`;

  }

  return str;

}



module.exports = ReplayDebugger;

devtools/server/actors/replay/replay.js

+35 −8
Original line number Diff line number Diff line
@@ -68,7 +68,9 @@ dbg.onNewGlobalObject = function(global) { 
// Utilities

///////////////////////////////////////////////////////////////////////////////



const dump = RecordReplayControl.dump;

const dump = str => {

  RecordReplayControl.dump(`[Child #${RecordReplayControl.childId()}]: ${str}`);

};



function assert(v) {

  if (!v) {
@@ -143,6 +145,24 @@ function isNonNullObject(obj) { 
  return obj && (typeof obj == "object" || typeof obj == "function");

}



function getMemoryUsage() {

  const memoryKinds = {

    Generic: [1],

    Snapshots: [2, 3, 4, 5, 6, 7],

    ScriptHits: [8],

  };



  const rv = {};

  for (const [name, kinds] of Object.entries(memoryKinds)) {

    let total = 0;

    kinds.forEach(kind => {

      total += RecordReplayControl.memoryUsage(kind);

    });

    rv[name] = total;

  }

  return rv;

}



///////////////////////////////////////////////////////////////////////////////

// Persistent Script State

///////////////////////////////////////////////////////////////////////////////
@@ -637,16 +657,16 @@ function ClearPausedState() { 
// The manifest that is currently being processed.

let gManifest;



// When processing "resume" manifests this tracks the execution time when we

// started execution from the initial checkpoint.

let gTimeWhenResuming;

// When processing certain manifests this tracks the execution time when the

// manifest started executing.

let gManifestStartTime;



// Handlers that run when a manifest is first received. This must be specified

// for all manifests.

const gManifestStartHandlers = {

  resume({ breakpoints }) {

    RecordReplayControl.resumeExecution();

    gTimeWhenResuming = RecordReplayControl.currentExecutionTime();

    gManifestStartTime = RecordReplayControl.currentExecutionTime();

    breakpoints.forEach(ensurePositionHandler);

  },
@@ -663,6 +683,7 @@ const gManifestStartHandlers = { 
  },



  scanRecording(manifest) {

    gManifestStartTime = RecordReplayControl.currentExecutionTime();

    gManifestStartHandlers.runToPoint(manifest);

  },
@@ -801,7 +822,7 @@ const gManifestFinishedAfterCheckpointHandlers = { 
  resume(_, point) {

    RecordReplayControl.manifestFinished({

      point,

      duration: RecordReplayControl.currentExecutionTime() - gTimeWhenResuming,

      duration: RecordReplayControl.currentExecutionTime() - gManifestStartTime,

      consoleMessages: gNewConsoleMessages,

      scripts: gNewScripts,

    });
@@ -818,7 +839,13 @@ const gManifestFinishedAfterCheckpointHandlers = { 


  scanRecording({ endpoint }, point) {

    if (point.checkpoint == endpoint) {

      RecordReplayControl.manifestFinished({ point });

      const duration =

        RecordReplayControl.currentExecutionTime() - gManifestStartTime;

      RecordReplayControl.manifestFinished({

        point,

        duration,

        memoryUsage: getMemoryUsage(),

      });

    }

  },

};
@@ -1068,7 +1095,7 @@ function getObjectData(id) { 
      optimizedOut: object.optimizedOut,

    };

  }

  throwError("Unknown object kind");

  throwError(`Unknown object kind: ${object}`);

}



function getObjectProperties(object) {

toolkit/recordreplay/MemorySnapshot.cpp

+7 −0
Original line number Diff line number Diff line
@@ -1312,5 +1312,12 @@ void RestoreMemoryToLastSavedDiffCheckpoint() { 
  gMemoryInfo->mSnapshotThreadsShouldRestore.ActivateEnd();

}



size_t GetMemoryUsage(MemoryKind aKind) {

  if (!gMemoryInfo) {

    return 0;

  }

  return gMemoryInfo->mMemoryBalance[(size_t)aKind];

}



}  // namespace recordreplay

}  // namespace mozilla

toolkit/recordreplay/MemorySnapshot.h

+3 −0
Original line number Diff line number Diff line
@@ -126,6 +126,9 @@ void MemoryMove(void* aDst, const void* aSrc, size_t aSize); 
// dynamic code loading.

void MemoryZero(void* aDst, size_t aSize);



// Get the amount of allocated memory used by data of the specified kind.

size_t GetMemoryUsage(MemoryKind aKind);



}  // namespace recordreplay

}  // namespace mozilla