fix: event with invalid timestamp in trace log #31349

CezaryKulakowski · 2021-10-08T10:00:21Z

When node is started within Electron's environment it doesn't
initialize v8 and time of v8's start is never set. As a result
we log v8's start time as 0 and it breaks timestamps in the
trace log. With this change we log v8's start time only when
it was initialized by node.

Bug: #31348

Description of Change

Checklist

PR description included and stakeholders cc'd
npm test passes
tests are changed or added
relevant documentation is changed or added
PR release notes describe the change in a way relevant to app developers, and are capitalized, punctuated, and past tense.

Release Notes

Notes: fixed event with invalid timestamp in trace log

deepak1556 · 2021-10-08T10:25:24Z

/cc @codebytere this is worth upstreaming.

deepak1556 · 2021-10-08T10:27:34Z

patches/node/.patches

@@ -14,6 +14,7 @@ chore_allow_the_node_entrypoint_to_be_a_builtin_module.patch
 chore_add_context_to_context_aware_module_prevention.patch
 chore_read_nobrowserglobals_from_global_not_process.patch
 enable_31_bit_smis_on_64bit_arch_and_ptr_compression.patch
+fix_event_with_invalid_timestamp_in_trace_log.patch


@CezaryKulakowski Is this patch order correct, looks like the sync failure is related to it. Can you please look into it.

@deepak1556 I've just checked again than gclient sync passes with no error on my Windows 10 and macOS.

I can also see that sync was fine on Windows. Is gclient run with some additional options on buildbots on macOS and Linux?

electron/.circleci/config.yml

Line 261 in 31e295a

ELECTRON_USE_THREE_WAY_MERGE_FOR_PATCHES=1 gclient sync --with_branch_heads --with_tags

is the command used by linux and macOS ci.

I've just run this command on top of my branch on macOS and gclient was successful.

I'm going to move my patch under another one which also modifies src/env.cc. Unfortunately I am not able to check locally if it works as there is no problem on my machines.

Yeah not sure what is the issue, /cc @jkleinsc

I'm going to move my patch under another one which also modifies src/env.cc

Sounds good, it is better if you can just append the patch to the list

It seems my fixup solved the problem. But it would be good to know how to reproduce the problem locally to avoid such problems in the future. I guess the best tip is to apply new patches on top of the rest of the patches and put it at the end of file .patches.

zcbenz · 2021-10-11T00:39:58Z

I wonder if we can set performance::performance_v8_start = PERFORMANCE_NOW() in ElectronRendererClient to avoid adding a patch?

CezaryKulakowski · 2021-10-11T07:41:08Z

@zcbenz we could but current fix looks like more valid one. I don't know the node's development process: is it possible to upstream this change to them?

zcbenz · 2021-10-11T10:12:26Z

We would like to minimize the number of patches on Node.js, so generally we prefer having ugly code in Electron than patching Node.js.

For this patch I think it should be fine to be upstreamed, can you try creating a pull request at https://github.com/nodejs/node? If Node.js maintainers are fine with it I have no problem merging this.

codebytere · 2021-10-11T10:46:04Z

@zcbenz i'll open an upsteam PR.

codebytere · 2021-10-11T10:52:33Z

Open at nodejs/node#40405

ckerr · 2021-10-13T18:05:44Z

linux-x64-testing-tests is failing with this error:

AssertionError: the trace output file is suspiciously large (116.525390625KB),
        check "/tmp/trace.json": expected 116.525390625 to be below 10
    at Context.<anonymous> (electron/spec-main/api-content-tracing-spec.ts:64:41)

Which superficially seems related to the subject of this PR. Is this related, and if so, is this an actual issue, or is it just that the file has changed because the timestamps have changed?

codebytere · 2021-10-14T09:12:29Z

@ckerr this was fixed in #31409 and is unrelated so @CezaryKulakowski if you could rebase we can get this merged.

When node is started within Electron's environment it doesn't initialize v8 and time of v8's start is never set. As a result we log v8's start time as 0 and it breaks timestamps in the trace log. With this change we log v8's start time only when it was initialized by node.

CezaryKulakowski · 2021-10-14T10:18:36Z

@codebytere I've force pushed branch rebased to the newest main.

release-clerk · 2021-10-14T14:08:37Z

Release Notes Persisted

fixed event with invalid timestamp in trace log

trop · 2021-10-14T14:09:08Z

I have automatically backported this PR to "14-x-y", please check out #31421

trop · 2021-10-14T14:09:11Z

I have automatically backported this PR to "15-x-y", please check out #31422

trop · 2021-10-14T14:09:14Z

I have automatically backported this PR to "16-x-y", please check out #31423

PR-URL: #40405 Refs: electron/electron#31349 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com>

When node is started within Electron's environment it doesn't initialize v8 and time of v8's start is never set. As a result we log v8's start time as 0 and it breaks timestamps in the trace log. With this change we log v8's start time only when it was initialized by node.

PR-URL: #40405 Refs: electron/electron#31349 Reviewed-By: Anna Henningsen <anna@addaleax.net> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Joyee Cheung <joyeec9h3@gmail.com>

CezaryKulakowski requested a review from a team as a code owner October 8, 2021 10:00

electron-cation bot added the new-pr 🌱 PR opened in the last 24 hours label Oct 8, 2021

CezaryKulakowski mentioned this pull request Oct 8, 2021

[Bug]: wrong timestamps in chromium trace logs #31348

Closed

3 tasks

deepak1556 added semver/patch backwards-compatible bug fixes target/14-x-y labels Oct 8, 2021

deepak1556 approved these changes Oct 8, 2021

View reviewed changes

deepak1556 reviewed Oct 8, 2021

View reviewed changes

electron-cation bot removed the new-pr 🌱 PR opened in the last 24 hours label Oct 9, 2021

zcbenz approved these changes Oct 11, 2021

View reviewed changes

codebytere mentioned this pull request Oct 11, 2021

src: ensure V8 initialized before marking milestone nodejs/node#40405

Closed

CezaryKulakowski force-pushed the issue_31348 branch from f658353 to 53cfb10 Compare October 14, 2021 10:17

codebytere approved these changes Oct 14, 2021

View reviewed changes

jkleinsc merged commit 11db6a7 into electron:main Oct 14, 2021

This was referenced Oct 14, 2021

fix: event with invalid timestamp in trace log #31421

Merged

fix: event with invalid timestamp in trace log #31422

Merged

fix: event with invalid timestamp in trace log #31423

Merged

trop bot added the in-flight/14-x-y label Oct 14, 2021

trop bot added in-flight/15-x-y and removed target/14-x-y labels Oct 14, 2021

trop bot added in-flight/16-x-y and removed target/15-x-y labels Oct 14, 2021

trop bot added merged/16-x-y and removed in-flight/16-x-y labels Oct 21, 2021

commit-lint bot mentioned this pull request Jan 18, 2022

[pull] main from electron:main Blaquez-home/electron#3

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

fix: event with invalid timestamp in trace log #31349

fix: event with invalid timestamp in trace log #31349

CezaryKulakowski commented Oct 8, 2021

deepak1556 commented Oct 8, 2021

deepak1556 Oct 8, 2021

CezaryKulakowski Oct 8, 2021

CezaryKulakowski Oct 8, 2021

deepak1556 Oct 8, 2021

CezaryKulakowski Oct 8, 2021

CezaryKulakowski Oct 8, 2021 •

edited

Loading

deepak1556 Oct 8, 2021

CezaryKulakowski Oct 8, 2021

zcbenz commented Oct 11, 2021

CezaryKulakowski commented Oct 11, 2021

zcbenz commented Oct 11, 2021

codebytere commented Oct 11, 2021

codebytere commented Oct 11, 2021

ckerr commented Oct 13, 2021

codebytere commented Oct 14, 2021 •

edited

Loading

CezaryKulakowski commented Oct 14, 2021

release-clerk bot commented Oct 14, 2021

trop bot commented Oct 14, 2021

trop bot commented Oct 14, 2021

trop bot commented Oct 14, 2021

fix: event with invalid timestamp in trace log #31349

fix: event with invalid timestamp in trace log #31349

Conversation

CezaryKulakowski commented Oct 8, 2021

Description of Change

Checklist

Release Notes

deepak1556 commented Oct 8, 2021

deepak1556 Oct 8, 2021

Choose a reason for hiding this comment

CezaryKulakowski Oct 8, 2021

Choose a reason for hiding this comment

CezaryKulakowski Oct 8, 2021

Choose a reason for hiding this comment

deepak1556 Oct 8, 2021

Choose a reason for hiding this comment

CezaryKulakowski Oct 8, 2021

Choose a reason for hiding this comment

CezaryKulakowski Oct 8, 2021 • edited Loading

Choose a reason for hiding this comment

deepak1556 Oct 8, 2021

Choose a reason for hiding this comment

CezaryKulakowski Oct 8, 2021

Choose a reason for hiding this comment

zcbenz commented Oct 11, 2021

CezaryKulakowski commented Oct 11, 2021

zcbenz commented Oct 11, 2021

codebytere commented Oct 11, 2021

codebytere commented Oct 11, 2021

ckerr commented Oct 13, 2021

codebytere commented Oct 14, 2021 • edited Loading

CezaryKulakowski commented Oct 14, 2021

release-clerk bot commented Oct 14, 2021

trop bot commented Oct 14, 2021

trop bot commented Oct 14, 2021

trop bot commented Oct 14, 2021

CezaryKulakowski Oct 8, 2021 •

edited

Loading

codebytere commented Oct 14, 2021 •

edited

Loading