diff --git a/draftlogs/7657_add.md b/draftlogs/7657_add.md new file mode 100644 index 00000000000..b2193a683c7 --- /dev/null +++ b/draftlogs/7657_add.md @@ -0,0 +1 @@ + - Add `Plotly.profile()` API method for performance profiling [[#7657](https://github.com/plotly/plotly.js/pull/7657)] diff --git a/draftlogs/XXXX_add.md b/draftlogs/XXXX_add.md new file mode 100644 index 00000000000..4990045e360 --- /dev/null +++ b/draftlogs/XXXX_add.md @@ -0,0 +1 @@ + - Add `Plotly.profile()` API method for performance profiling [[#XXXX](https://github.com/plotly/plotly.js/pull/XXXX)] diff --git a/src/lib/index.js b/src/lib/index.js index 90d38b5fde5..3f6a67ceead 100644 --- a/src/lib/index.js +++ b/src/lib/index.js @@ -1413,3 +1413,5 @@ lib.getPositionFromD3Event = function () { return [d3.event.offsetX, d3.event.offsetY]; } }; + +lib.Profiler = require('./profiler'); diff --git a/src/lib/profiler.js b/src/lib/profiler.js new file mode 100644 index 00000000000..59e1e78064e --- /dev/null +++ b/src/lib/profiler.js @@ -0,0 +1,48 @@ +'use strict'; + +/** + * Profiler utility for collecting render timing data + * + * Usage: + * var profiler = Profiler.start(gd); + * // ... do work ... + * profiler.mark('phaseName'); + * // ... do more work ... + * profiler.end(); + */ + +exports.isEnabled = function(gd) { + return gd && gd._profileEnabled === true; +}; + +exports.start = function(gd) { + if(!exports.isEnabled(gd)) { + return { + mark: function() {}, + end: function() {} + }; + } + + var startTime = performance.now(); + var lastMark = startTime; + var phases = {}; + + return { + mark: function(phaseName) { + var now = performance.now(); + phases[phaseName] = { + duration: now - lastMark, + timestamp: now - startTime + }; + lastMark = now; + }, + end: function() { + var endTime = performance.now(); + return { + total: endTime - startTime, + phases: phases, + timestamp: new Date().toISOString() + }; + } + }; +}; diff --git a/src/plot_api/index.js b/src/plot_api/index.js index 011ff30ba1c..538a68e675a 100644 --- a/src/plot_api/index.js +++ b/src/plot_api/index.js @@ -37,3 +37,5 @@ exports.downloadImage = require('../snapshot/download'); var templateApi = require('./template_api'); exports.makeTemplate = templateApi.makeTemplate; exports.validateTemplate = templateApi.validateTemplate; + +exports.profile = require('./profile'); diff --git a/src/plot_api/plot_api.js b/src/plot_api/plot_api.js index 470900c768f..a89c965222b 100644 --- a/src/plot_api/plot_api.js +++ b/src/plot_api/plot_api.js @@ -30,6 +30,8 @@ var helpers = require('./helpers'); var subroutines = require('./subroutines'); var editTypes = require('./edit_types'); +var Profiler = require('../lib').Profiler; + var AX_NAME_PATTERN = require('../plots/cartesian/constants').AX_NAME_PATTERN; var numericNameWarningCount = 0; @@ -64,6 +66,9 @@ function _doPlot(gd, data, layout, config) { // Events.init is idempotent and bails early if gd has already been init'd Events.init(gd); + // Start profiler if enabled (returns no-op if disabled) + var profiler = Profiler.start(gd); + if (Lib.isPlainObject(data)) { var obj = data; data = obj.data; @@ -129,6 +134,7 @@ function _doPlot(gd, data, layout, config) { } Plots.supplyDefaults(gd); + profiler.mark('supplyDefaults'); var fullLayout = gd._fullLayout; var hasCartesian = fullLayout._has('cartesian'); @@ -145,6 +151,7 @@ function _doPlot(gd, data, layout, config) { delete fullLayout._shouldCreateBgLayer; } } + profiler.mark('makePlotFramework'); // clear gradient and pattern defs on each .plot call, because we know we'll loop through all traces Drawing.initGradients(gd); @@ -159,6 +166,7 @@ function _doPlot(gd, data, layout, config) { // to force redoing calcdata, just delete it before calling _doPlot var recalc = !gd.calcdata || gd.calcdata.length !== (gd._fullData || []).length; if (recalc) Plots.doCalcdata(gd); + profiler.mark('doCalcdata'); // in case it has changed, attach fullData traces to calcdata for (var i = 0; i < gd.calcdata.length; i++) { @@ -351,11 +359,28 @@ function _doPlot(gd, data, layout, config) { return Axes.draw(gd, graphWasEmpty ? '' : 'redraw'); } - var seq = [Plots.previousPromises, addFrames, drawFramework, marginPushers, marginPushersAgain]; + var seq = [ + Plots.previousPromises, + addFrames, + drawFramework, + function() { profiler.mark('drawFramework'); }, + marginPushers, + function() { profiler.mark('marginPushers'); }, + marginPushersAgain, + function() { profiler.mark('marginPushersAgain'); } + ]; - if (hasCartesian) seq.push(positionAndAutorange); + if (hasCartesian) { + seq.push( + positionAndAutorange, + function() { profiler.mark('positionAndAutorange'); } + ); + } - seq.push(subroutines.layoutStyles); + seq.push( + subroutines.layoutStyles, + function() { profiler.mark('layoutStyles'); } + ); if (hasCartesian) { seq.push(drawAxes, function insideTickLabelsAutorange(gd) { var insideTickLabelsUpdaterange = gd._fullLayout._insideTickLabelsUpdaterange; @@ -367,12 +392,16 @@ function _doPlot(gd, data, layout, config) { }); } }); + seq.push(function() { profiler.mark('drawAxes'); }); } seq.push( subroutines.drawData, + function() { profiler.mark('drawData'); }, subroutines.finalDraw, + function() { profiler.mark('finalDraw'); }, initInteractions, + function() { profiler.mark('initInteractions'); }, Plots.addLinks, Plots.rehover, Plots.redrag, @@ -391,6 +420,13 @@ function _doPlot(gd, data, layout, config) { if (!plotDone || !plotDone.then) plotDone = Promise.resolve(); return plotDone.then(function () { + // Finalize profiling and emit event if profiling is enabled + var profileData = profiler.end(); + if (profileData && profileData.total) { + gd._profileData = profileData; + Events.triggerHandler(gd, 'plotly_profiled', profileData); + } + emitAfterPlot(gd); return gd; }); diff --git a/src/plot_api/profile.js b/src/plot_api/profile.js new file mode 100644 index 00000000000..d0b93f86c91 --- /dev/null +++ b/src/plot_api/profile.js @@ -0,0 +1,42 @@ +'use strict'; + +var Lib = require('../lib'); + +/** + * Enable or disable performance profiling on a graph div + * + * @param {string|HTMLDivElement} gd - Graph div or its id + * @param {boolean} [enable=true] - Whether to enable profiling + * @returns {Object|null} - Current profile data if available, null otherwise + * + * Usage: + * Plotly.profile('myDiv'); // Enable profiling + * Plotly.profile('myDiv', true); // Enable profiling + * Plotly.profile('myDiv', false); // Disable profiling + * + * After each render, profile data is available via: + * gd._profileData // Latest profile result + * gd.on('plotly_profiled', function(data) { ... }); // Event listener + */ +function profile(gd, enable) { + gd = Lib.getGraphDiv(gd); + + if(!Lib.isPlotDiv(gd)) { + Lib.warn('profile() called on non-plot element'); + return null; + } + + // Default to enabling + if(enable === undefined) enable = true; + + gd._profileEnabled = !!enable; + + if(!enable) { + // Clear profile data when disabling + delete gd._profileData; + } + + return gd._profileData || null; +} + +module.exports = profile; diff --git a/test/jasmine/tests/profile_test.js b/test/jasmine/tests/profile_test.js new file mode 100644 index 00000000000..233640026c7 --- /dev/null +++ b/test/jasmine/tests/profile_test.js @@ -0,0 +1,222 @@ +'use strict'; + +var Plotly = require('../../../lib/index'); +var Lib = require('../../../src/lib'); +var createGraphDiv = require('../assets/create_graph_div'); +var destroyGraphDiv = require('../assets/destroy_graph_div'); + +describe('Plotly.profile', function() { + var gd; + + beforeEach(function() { + gd = createGraphDiv(); + }); + + afterEach(destroyGraphDiv); + + describe('API', function() { + it('should be a function', function() { + expect(typeof Plotly.profile).toBe('function'); + }); + + it('should enable profiling when called with true or no argument', function(done) { + Plotly.newPlot(gd, [{y: [1, 2, 3]}]) + .then(function() { + Plotly.profile(gd); + expect(gd._profileEnabled).toBe(true); + + Plotly.profile(gd, false); + expect(gd._profileEnabled).toBe(false); + + Plotly.profile(gd, true); + expect(gd._profileEnabled).toBe(true); + }) + .then(done, done.fail); + }); + + it('should warn when called on non-plot element', function() { + spyOn(Lib, 'warn'); + var div = document.createElement('div'); + Plotly.profile(div); + expect(Lib.warn).toHaveBeenCalled(); + }); + + it('should return null for non-plot element', function() { + var div = document.createElement('div'); + var result = Plotly.profile(div); + expect(result).toBeNull(); + }); + + it('should clear profile data when disabling', function(done) { + Plotly.newPlot(gd, [{y: [1, 2, 3]}]) + .then(function() { + Plotly.profile(gd, true); + return Plotly.react(gd, [{y: [4, 5, 6]}]); + }) + .then(function() { + expect(gd._profileData).toBeDefined(); + Plotly.profile(gd, false); + expect(gd._profileData).toBeUndefined(); + }) + .then(done, done.fail); + }); + }); + + describe('profiling data collection', function() { + it('should collect timing data after render when enabled', function(done) { + Plotly.newPlot(gd, [{y: [1, 2, 3]}]) + .then(function() { + Plotly.profile(gd, true); + return Plotly.react(gd, [{y: [4, 5, 6]}]); + }) + .then(function() { + expect(gd._profileData).toBeDefined(); + expect(gd._profileData.total).toBeGreaterThan(0); + expect(gd._profileData.phases).toBeDefined(); + expect(gd._profileData.timestamp).toBeDefined(); + }) + .then(done, done.fail); + }); + + it('should not collect timing data when disabled', function(done) { + Plotly.newPlot(gd, [{y: [1, 2, 3]}]) + .then(function() { + Plotly.profile(gd, false); + delete gd._profileData; // Clear any existing data + return Plotly.react(gd, [{y: [4, 5, 6]}]); + }) + .then(function() { + expect(gd._profileData).toBeUndefined(); + }) + .then(done, done.fail); + }); + + it('should emit plotly_profiled event', function(done) { + var eventData = null; + + Plotly.newPlot(gd, [{y: [1, 2, 3]}]) + .then(function() { + Plotly.profile(gd, true); + gd.on('plotly_profiled', function(data) { + eventData = data; + }); + return Plotly.react(gd, [{y: [4, 5, 6]}]); + }) + .then(function() { + expect(eventData).not.toBeNull(); + expect(eventData.total).toBeGreaterThan(0); + expect(eventData.phases).toBeDefined(); + }) + .then(done, done.fail); + }); + + it('should update profile data on each render', function(done) { + var firstProfileData; + + Plotly.newPlot(gd, [{y: [1, 2, 3]}]) + .then(function() { + Plotly.profile(gd, true); + return Plotly.react(gd, [{y: [4, 5, 6]}]); + }) + .then(function() { + firstProfileData = gd._profileData; + expect(firstProfileData).toBeDefined(); + return Plotly.react(gd, [{y: [7, 8, 9]}]); + }) + .then(function() { + expect(gd._profileData).toBeDefined(); + // Timestamps should be different + expect(gd._profileData.timestamp).not.toBe(firstProfileData.timestamp); + }) + .then(done, done.fail); + }); + }); + + describe('phase timing', function() { + it('should include expected phases', function(done) { + Plotly.newPlot(gd, [{y: [1, 2, 3]}]) + .then(function() { + Plotly.profile(gd, true); + return Plotly.react(gd, [{y: [4, 5, 6]}]); + }) + .then(function() { + var phases = gd._profileData.phases; + expect(phases.supplyDefaults).toBeDefined(); + expect(phases.doCalcdata).toBeDefined(); + }) + .then(done, done.fail); + }); + + it('should have duration and timestamp for each phase', function(done) { + Plotly.newPlot(gd, [{y: [1, 2, 3]}]) + .then(function() { + Plotly.profile(gd, true); + return Plotly.react(gd, [{y: [4, 5, 6]}]); + }) + .then(function() { + var phases = gd._profileData.phases; + var phaseNames = Object.keys(phases); + + expect(phaseNames.length).toBeGreaterThan(0); + + phaseNames.forEach(function(name) { + var phase = phases[name]; + expect(typeof phase.duration).toBe('number'); + expect(phase.duration).toBeGreaterThanOrEqual(0); + expect(typeof phase.timestamp).toBe('number'); + expect(phase.timestamp).toBeGreaterThanOrEqual(0); + }); + }) + .then(done, done.fail); + }); + + it('should include async phases after full render', function(done) { + Plotly.newPlot(gd, [{y: [1, 2, 3]}]) + .then(function() { + Plotly.profile(gd, true); + return Plotly.react(gd, [{y: [4, 5, 6]}]); + }) + .then(function() { + var phases = gd._profileData.phases; + // These are the async phases added in Phase 4 + expect(phases.drawFramework).toBeDefined(); + expect(phases.drawData).toBeDefined(); + }) + .then(done, done.fail); + }); + }); + + describe('different trace types', function() { + it('should work with bar traces', function(done) { + Plotly.newPlot(gd, [{type: 'bar', y: [1, 2, 3]}]) + .then(function() { + Plotly.profile(gd, true); + return Plotly.react(gd, [{type: 'bar', y: [4, 5, 6]}]); + }) + .then(function() { + expect(gd._profileData).toBeDefined(); + expect(gd._profileData.total).toBeGreaterThan(0); + }) + .then(done, done.fail); + }); + + it('should work with multiple traces', function(done) { + Plotly.newPlot(gd, [ + {y: [1, 2, 3]}, + {y: [3, 2, 1]} + ]) + .then(function() { + Plotly.profile(gd, true); + return Plotly.react(gd, [ + {y: [4, 5, 6]}, + {y: [6, 5, 4]} + ]); + }) + .then(function() { + expect(gd._profileData).toBeDefined(); + expect(gd._profileData.total).toBeGreaterThan(0); + }) + .then(done, done.fail); + }); + }); +});