Fix #7459 -- allow parallel timers of the same name.

[busykai]

Fix #7459.

Keep track of the measurements of the same name started in parallel: assign them different tracking ids, but report them under the same name. All the measurements are now PerfMeasurement objects. Also, code cleanup.

CC: @redmunds, @peterflynn -- please take a look if this change is a good idea.

[busykai]

Too bad Chromium does not support destructuring assignments.

[ingorichter]

Yeah, I'm so glad that somebody picked this up. 👍

[redmunds]

@busykai Is this to get rid of the "Performance measurement {id} is already defined" error message? If so, do you have a specific scenario that causes this problem?

Every time I have seen this problem it's because the calls to start (markStart()) and end (addMeasurement()/finalizeMeasurement()) a timer were mismatched. For example, a timer measuring an async operation is ended in done() callback but not in fail() callback.

Your code will eliminate the error message in that case, but the timer will still never end, so the results will be skewed. And now we won't get an error message to indicate that something's broken.

FYI, you can have parallel timers with current code, but it's up to caller to generate unique names.

[busykai]

@redmunds, this is to get rid of "Recursive tests with the same name are not supported...", a different situation. A simple use case is when you have a "slow" linter installed and quickly switch back and forth between files. In some cases (e.g. XDK where the fs is slower or when we were opening binary files in Brackets) you could see the same thing from the fs (I guess it was FileUtils.readAsText()).

Here's a simple patch which would always inflict the problem described in #7459:

diff --git a/src/language/CodeInspection.js b/src/language/CodeInspection.js
index cb6f984..21bdf3d 100644
--- a/src/language/CodeInspection.js
+++ b/src/language/CodeInspection.js
@@ -193,6 +193,7 @@ define(function (require, exports, module) {
         DocumentManager.getDocumentText(file)
             .done(function (fileText) {
                 var perfTimerInspector = PerfUtils.markStart("CodeInspection:\t" + file.fullPath),
+                    perfTimerInspector1 = PerfUtils.markStart("CodeInspection:\t" + file.fullPath),
                     masterPromise;

                 masterPromise = Async.doInParallel(providerList, function (provider) {
@@ -252,6 +253,7 @@ define(function (require, exports, module) {
                         return providerList.indexOf(a.provider) - providerList.indexOf(b.provider);
                     });
                     PerfUtils.addMeasurement(perfTimerInspector);
+                    PerfUtils.addMeasurement(perfTimerInspector1);
                     response.resolve(results);
                 });

FYI, you can have parallel timers with current code, but it's up to caller to generate unique names.

Yes, but doing that type of book keeping in all the places is a lot of extra code. Most of the callers would simply generate a descriptive string and pass it to the markStart and I think we need to keep it that way.

[redmunds]

this.reent is used before being set.

[redmunds]

I wrote this extension to test this:

/*jslint vars: true, plusplus: true, devel: true, nomen: true, indent: 4, maxerr: 50 */
/*global define, brackets */

define(function (require, exports, module) {
    "use strict";

    var CommandManager  = brackets.getModule("command/CommandManager"),
        Menus           = brackets.getModule("command/Menus"),
        PerfUtils       = brackets.getModule("utils/PerfUtils");

    var timerId = "redmunds.timer";

    function test() {
        var perfTimer1 = PerfUtils.markStart(timerId),
            perfTimer2 = PerfUtils.markStart(timerId);

        window.setTimeout(function () {
            PerfUtils.addMeasurement(perfTimer1);
            PerfUtils.addMeasurement(perfTimer2);

            var perfData = PerfUtils.getData();

            window.console.log("perfTimer1: " + perfData[perfTimer1]);
            window.console.log("perfTimer2: " + perfData[perfTimer2]);
            window.console.log(timerId + ": " + perfData[timerId]);
        }, 100);
    }

    Menus.getMenu("debug-menu").addMenuItem(
        CommandManager.register("Recursive PerfUtils Test", "redmunds.test", test)
    );
});

When I run it, the results written to console are:

perfTimer1: 100,100
perfTimer2: undefined
redmunds.timer: 100,100

Why is perfTimer2 undefined?

I expected markStart() to return a unique id for my timer that I can use to get my result for this operation. If I get an array of all results for this id, then I don't know which one was for this particular operation.

[redmunds]

I played around with this some more, and I guess perfData[perfTimer2] doesn't make sense because perfTimer2 is an Object. I think I was confused because perfData[perfTimer1] does return a value.

[busykai]

@redmunds, thanks for bringing up this use case.

The reason for the second timer being undefined is because I use the fact that the array key is always a string and have overridden PerfMeasurement toString implementation for internal convenience (measurements are tracked by ids, reported by names). Didn't take into account the fact that global perf data could be returned by getData(id). To illustrate it, here is the modified version of the extension that would work as you would expect it to:

/*jslint vars: true, plusplus: true, devel: true, nomen: true, indent: 4, maxerr: 50 */
/*global define, brackets */

define(function (require, exports, module) {
    "use strict";

    var CommandManager  = brackets.getModule("command/CommandManager"),
        Menus           = brackets.getModule("command/Menus"),
        PerfUtils       = brackets.getModule("utils/PerfUtils");

    var timerId = "redmunds.timer";

    function test() {
        var perfTimer1 = PerfUtils.markStart(timerId),
            perfTimer2 = PerfUtils.markStart(timerId);

        window.setTimeout(function () {
            PerfUtils.addMeasurement(perfTimer1);
            PerfUtils.addMeasurement(perfTimer2);

            var perfData1 = PerfUtils.getData(perfTimer1);
            var perfData2 = PerfUtils.getData(perfTimer2);
            var perfData = PerfUtils.getData();

            window.console.log("perfTimer1: " + perfData1);
            window.console.log("perfTimer2: " + perfData2);
            // NB: here is the issue, the "opaque" timer object should have the same
            // behaviour as if timerId was used.
            window.console.log(timerId + ": " + perfData[timerId]);
        }, 100);
    }

    Menus.getMenu("debug-menu").addMenuItem(
        CommandManager.register("Recursive PerfUtils Test", "redmunds.test", test)
    );
});

So I guess I will use explicit measurement.id where needed internally and make PerfMeasurement.toString() to use this.name instead of this.id to preserve the API intact. Makes sense? Let me know and I'll make the change.

[redmunds]

@busykai

So I guess I will use explicit measurement.id where needed internally and make PerfMeasurement.toString() to use this.name instead of this.id to preserve the API intact. Makes sense? Let me know and I'll make the change.

Yes, that makes sense

[busykai]

@redmunds, addressed your comments.

[redmunds]

Thanks! Merging.

[le717]

Yea! :D