1563239 - Events caught in our "Build Faster" support are summarized to the "dynamic" process

Status: RESOLVED FIXED

(Toolkit :: Telemetry, defect, P3)

Description

[Chris H-C :chutten]

Our "Build Faster" event support, aka dynamic builtin events, is supposed to look exactly as though the build was slow. Events should appear in the process they were recorded in, even though dynamically-registered events all end up in the "dynamic" process.

Event Summary has two keyed scalars for recording how many events are recorded: one for statically-registered events that put the events in their recording process, and one for dynamically-registered events that put the events in the "dynamic" process.

At present, dynamic builtin events are summarized to the "dynamic" one because we don't check if the dynamic event is built-in or not before summarizing.

Pretty sure we just need a && !(*gDynamicEventInfo)[eventKey->id].builtin in there.

Comment 1

[Jan-Erik Rediger [:janerik]]

To help Mozilla out with this bug, here's the steps:

1. Comment here on the bug that you want to volunteer to help. I (or someone else) will assign it to you.
2. Download and build the Firefox source code: https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Build_Instructions/Simple_Firefox_build
   • If you have any problems, please ask on IRC (https://wiki.mozilla.org/Irc) in the #introduction channel. They're there to help you get started.
   • You can also read the Developer Guide, which has answers to most development questions: https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/Introduction
3. Start working on this bug.

• Open toolkit/components/telemetry/core/TelemetryEvent.cpp. Line 465 is the buggy line.
• Above on line 446 in the if we have the right expression already: eventKey->dynamic && !(*gDynamicEventInfo)[eventKey->id].builtin
• Put this expression into its own line and assign to a variable: auto dynamicNonBuiltin = ...
• Use this variable in both the if condition and in the function call further below.
• If you have any problems with this bug, please comment on this bug and set the needinfo flag for me. Also, you can find me and my teammates on the #telemetry channel on IRC (https://wiki.mozilla.org/Irc) most hours of most days.

1. Build your change with mach build and test your change with mach test toolkit/components/telemetry/tests/. Also check your changes for adherence to our style guidelines by using mach lint
2. Submit the patch (including an automated test, if applicable) for review. Mark me as a reviewer so I'll get an email to come look at your code.
   • Here's the guide: https://developer.mozilla.org/en-US/docs/Mozilla/Developer_guide/How_to_Submit_a_Patch
3. After a series of reviews and changes to your patch, I'll mark it for checkin or push it to autoland. Your code will soon be shipping to Firefox users worldwide!
4. ...now you get to think about what kind of bug you'd like to work on next. Let me know what you're interested in and I can help you find your next contribution.

Comment 2

[singuliere]

I want to volunteer for this bug.

Comment 3

[singuliere]

Attachment: Bug 1563239 - Do not summarize builtin events to the "dynamic" process

Check if the dynamic event is built-in or not before summarizing.

Comment 4

[Jan-Erik Rediger [:janerik]]

Thanks for volunteering and submitting a patch right away. I will take a look later today.
One thing I can already see: can you be so kind and change the commit title to Bug 1563239 - Do not summarize builtin events to the "dynamic" process? (That's just the default format of commit titles we use, a bit of consistency here is nice)

Comment 5

[singuliere]

Thanks for the immediate feedback, much appreciated :-) I'll update the title, sure.

For the record I chose the format XXX (Bug NNNN) because it is shown in the tutorial at https://moz-conduit.readthedocs.io/en/latest/arcanist-user.html#the-initial-patch

Comment 6

[singuliere]

The suggested method to run tests (./mach test toolkit/components/telemetry/tests/) fails with:

 0:22.39 ========================== 10 passed in 0.05 seconds ===========================
 0:22.39 Return code from mach python-test: 0
usage: mach [-h] [--binary BINARY] [--address ADDRESS] [--emulator]
            [--app APP] [--app-arg APP_ARGS] [--profile PROFILE]
            [--setpref PREF=VALUE] [--preferences PREFS_FILES]
            [--addon ADDONS] [--repeat REPEAT] [--run-until-failure]
            [--testvars TESTVARS] [--symbols-path SYMBOLS_PATH]
            [--socket-timeout SOCKET_TIMEOUT]
            [--startup-timeout STARTUP_TIMEOUT] [--shuffle]
            [--shuffle-seed SHUFFLE_SEED] [--total-chunks TOTAL_CHUNKS]
            [--this-chunk THIS_CHUNK] [--server-root SERVER_ROOT]
            [--gecko-log GECKO_LOG] [--logger-name LOGGER_NAME] [--jsdebugger]
            [--pydebugger PYDEBUGGER] [--disable-e10s] [--enable-webrender]
            [-z] [--tag TEST_TAGS] [--workspace WORKSPACE] [-v]
            [--emulator-binary EMULATOR_BIN] [--adb ADB_PATH] [--avd AVD]
            [--avd-home AVD_HOME] [--device DEVICE_SERIAL]
            [--package PACKAGE_NAME] [--log-raw LOG_RAW] [--log-html LOG_HTML]
            [--log-tbpl LOG_TBPL] [--log-xunit LOG_XUNIT]
            [--log-unittest LOG_UNITTEST] [--log-grouped LOG_GROUPED]
            [--log-mach LOG_MACH] [--log-raw-level LOG_RAW_LEVEL]
            [--log-tbpl-compact] [--log-tbpl-level LOG_TBPL_LEVEL]
            [--log-tbpl-buffer LOG_TBPL_BUFFER] [--log-mach-verbose]
            [--log-mach-screenshot] [--log-mach-level LOG_MACH_LEVEL]
            [--log-mach-buffer LOG_MACH_BUFFER] [--log-mach-no-screenshot]
            [tests [tests ...]]
mach: error: Test file(s) not found: toolkit/components/telemetry/tests/marionette/tests/client/test_event_ping.py toolkit/components/telemetry/tests/marionette/tests/client/test_main_tab_scalars.py toolkit/components/telemetry/tests/marionette/tests/client/test_optout_ping.py toolkit/components/telemetry/tests/marionette/tests/client/test_search_counts_across_sessions.py toolkit/components/telemetry/tests/marionette/tests/client/test_subsession_management.py toolkit/components/telemetry/tests/marionette/tests/unit/test_ping_server_received_ping.py

I'll try to figure out why this is.

Comment 7

[Jan-Erik Rediger [:janerik]]

Re commit title: ah well, different modules use slightly different commit message formats.

re test: try running ./mach test toolkit/components/telemetry/test/unit and ./mach test toolkit/components/telemetry/test/browser

Comment 8

[singuliere]

The tests running with ./mach test toolkit/components/telemetry/tests/unit and ./mach test toolkit/components/telemetry/tests/browser pass, thanks for the hint :-)

Comment 9

[Jan-Erik Rediger [:janerik]]

Hey, the code looks good and seems to be working. Unfortunately we ourselves don't have a test for that yet (which is the whole reason this bug existed in the first place.
I went ahead and quickly extend a test, would you be so kind to also include that in your changeset?

Just apply this patch:

diff --git c/toolkit/components/telemetry/tests/unit/test_TelemetryEvents_buildFaster.js w/toolkit/components/telemetry/tests/unit/test_TelemetryEvents_buildFaster.js
index 7c38c42392540..a1300f9e1e5ec 100644
--- c/toolkit/components/telemetry/tests/unit/test_TelemetryEvents_buildFaster.js
+++ w/toolkit/components/telemetry/tests/unit/test_TelemetryEvents_buildFaster.js
@@ -164,6 +164,7 @@ add_task(
 
 add_task(async function test_dynamicBuiltinEvents() {
   Telemetry.clearEvents();
+  Telemetry.clearScalars();
   Telemetry.canRecordExtended = true;
 
   const TEST_EVENT_NAME = "telemetry.test.dynamicbuiltin";
@@ -200,6 +201,9 @@ add_task(async function test_dynamicBuiltinEvents() {
   );
   Assert.ok("parent" in snapshot, "Should have parent events in the snapshot.");
 
+  // For checking event summaries
+  const scalars = Telemetry.getSnapshotForKeyedScalars("main", true);
+
   let expected = [
     [TEST_EVENT_NAME, "test1", "object1"],
     [TEST_EVENT_NAME, "test2", "object1", null, { key1: "foo", key2: "bar" }],
@@ -217,6 +221,10 @@ add_task(async function test_dynamicBuiltinEvents() {
       expected[i],
       "Should have recorded the expected event data."
     );
+
+    const uniqueEventName = `${expected[i][0]}#${expected[i][1]}#${expected[i][2]}`;
+    const summaryCount = scalars.parent["telemetry.event_counts"][uniqueEventName];
+    Assert.equal(1, summaryCount, `${uniqueEventName} had wrong summary count`);
   }
 });

Comment 10

[singuliere]

I'll do that right away. Thanks for providing the patch: you make it super easy for the newcomer, kudos :-)

Comment 11

[singuliere]

For the record, the test is verified to fail without the fix and succeed with it. I used to following commands to do that without waiting for a full build: ./mach build toolkit/components/telemetry/ followed by ./mach test toolkit/components/telemetry/tests/unit/test_TelemetryEvents_buildFaster.js

Comment 12

[singuliere]

I think your comments were addressed. Please let me know if I should do anything differently. Thanks :-)

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e7ff4966b99e
Do not summarize builtin events to the "dynamic" process r=janerik

Comment 14

[Ethan Tseng [:ethan]]

singuliere,
Great work! Thanks for your contribution. Really appreciated!

Comment 15

[Natalia Csoregi [:nataliaCs]]

https://hg.mozilla.org/mozilla-central/rev/e7ff4966b99e

Comment 16

[singuliere]

I look forward to contributing more, it was a really nice experience :-)