New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 892184 link

Starred by 1 user

Issue metadata

Status: Assigned
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 2
Type: ----

Blocked on:
issue 892185



Sign in to add a comment

system_health.common_desktop/multitab:misc:typical24:2018 failing

Project Member Reported by sheriff-...@appspot.gserviceaccount.com, Oct 4

Issue description

Blockedon: 892185
Cc: -crouleau@google.com crouleau@chromium.org
Components: Speed>Benchmarks>Waterfall
Owner: nedngu...@google.com
Status: Assigned (was: Available)
THe log of the failing test is in https://chrome-swarming.appspot.com/task?id=4058267633e1b210&refresh=10&show_raw=1

(ERROR) 2018-10-04 06:57:58,286 page_test_results.Fail:540  Failure recorded: TraceImportError: Unexpected token Ö in JSON at position 0

    at JSON.parse (<anonymous>)

    at TraceEventImporter.createAsyncSlices_ (/tracing/extras/importer/trace_event_importer.html:1646:31)

    at TraceEventImporter.importEvents (/tracing/extras/importer/trace_event_importer.html:1151:12)

    at importer (/tracing/importer/import.html:198:65)

    at task.subTask (/tracing/importer/import.html:145:32)

    at Task.run (/tracing/base/task.html:80:50)

    at Function.Task.RunSynchronously (/tracing/base/task.html:125:25)

    at Import.importTraces (/tracing/importer/import.html:74:17)

    at createModelFromTraceData (c:\b\s\w\ir\third_party\catapult\tracing\tracing\mre\map_single_trace_cmdline.html:38:9)

    at eval (c:\b\s\w\ir\third_party\catapult\tracing\tracing\mre\map_single_trace_cmdline.html:57:25)



Looks like another character encoding issue. Ned, since you worked on  issue 891747 , could you check this out? Potentially it's related to your fix?
Cc: nednguyen@chromium.org
Owner: tdres...@chromium.org
No, this is tracing & metrics's realm. I reassign this to Tim for triaging.
Project Member

Comment 4 by bugdroid1@chromium.org, Oct 4

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/9e90a7878fd66ffc8280383f2f1033ffd002e82c

commit 9e90a7878fd66ffc8280383f2f1033ffd002e82c
Author: Caleb Rouleau <crouleau@chromium.org>
Date: Thu Oct 04 16:14:46 2018

[perfbot-sheriff] Disable failing multitab:misc:typical24:2018

NOTRY=true
TBR=nednguyen@google.com

Bug: 892184
Change-Id: I8df9415f42ee83de7dba675cbb8aeb1ec2db5f48
Reviewed-on: https://chromium-review.googlesource.com/c/1262195
Reviewed-by: Caleb Rouleau <crouleau@chromium.org>
Commit-Queue: Caleb Rouleau <crouleau@chromium.org>
Cr-Commit-Position: refs/heads/master@{#596694}
[modify] https://crrev.com/9e90a7878fd66ffc8280383f2f1033ffd002e82c/tools/perf/expectations.config

Cc: sullivan@google.com
This is an issue with trace importing, which I would have considered out of the scope of the metrics team.

Annie, any thoughts on which side of the fence this should fall on?
Cc: eyaich@chromium.org
This probably falls on our side of the fence. Emily, would you be able to take a look?
Cc: tdres...@chromium.org
Owner: eyaich@chromium.org
Sure I will take a look.
Cc: perezju@chromium.org cbruni@chromium.org
So it looks like this hasn't ever worked since it landed in https://chromium-review.googlesource.com/c/chromium/src/+/1228113 on 10/1. 

I was able to reproduce locally so I will dig in now.  

Adding cbruni@ and perezju@ since they authored and reviewed the benchmark to see if they have any insight since they know the benchmark better.
This is same as issue 828917, the problem was there even before the re-recording of the story from #8.
Ok, so I am having trouble determining the cause here. 

When I debug through this, the value is ":1:mbox:target-global-mbox" which is not encoded so when we try to decode it it returns ÖfèÆÖ«ë`†Úfè which is obviously not valid json.  

I am trying to determine if strings are still base64 encoded for blink.user_timing events in chrome (https://cs.chromium.org/chromium/src/third_party/catapult/tracing/tracing/extras/importer/trace_event_importer.html?l=1646).  

I was trying to find a benchmark that produced a trace that successfully executed this code and I have come up short.  Does anyone have any ideas for a valid use case that exercises this code?
Cc: skobes@chromium.org
Steve may be able to help with #10
Cc: -nednguyen@chromium.org nedngu...@google.com
I have no experience with the trace importing code but it looks like the base64 thing is a proposed convention for mark names in the User Timing API.

https://codereview.chromium.org/1573643002/

https://docs.google.com/document/d/1-44PszmhQ0-M6Sf2dZpVu-9jAOa7w2_vKAKckRWXJms/edit

-----
Convention 2: A / in a markName will indicate that the remaining text is a base64 encoded dictionary about the arguments of that measure. E.g:

    measure("Task1/eyJzdGVwcyI6M30=", "startSubPieceA", "endTask1");

Indicates that Task1 had {"steps":3}as its arguments.
-----
Right, I saw that convention last week which is why I am guessing it is a bug on the user timing side that the values are not getting encoded correctly.  

If the parsing fails in the importer should we just log a warning and skip importing the event?

I am going to try and dig into the user timing trace events to see if I can identify where it is coming from.  If there is someone that might have better knowledge of that code let me know.
Cc: npm@chromium.org
So after trying to log some info in the chrome code and determine what is going wrong, I am concluding that this is most likely user error.  

Codesearch for blink.user_timing and it appears to just pass in the mark name from the call to performance.mark, which according to https://www.w3.org/TR/user-timing/ can be an arbitrary string. 

From this document: https://docs.google.com/document/d/1-44PszmhQ0-M6Sf2dZpVu-9jAOa7w2_vKAKckRWXJms/edit# we are assuming that the name has optional args encoded at the end (although this isn't noted in the external documentation https://www.w3.org/TR/user-timing/) and I don't think the user intended that in this case. 

Therefore, I proposed for now that we make this code more robust to failure and just skip over events that don't parse correctly with an error message.  The risk here is that we skip over valid events.  

In this failure case the full name is the "measure_adobe_target_visitor_id:request:1:mbox:target-global-mbox".  This got parsed to assume that after the second ":" was actually the args, but I am guessing that GroupName = measure_adobe_target_visitor_id and task name = request:1:mbox:target-global-mbox, but only the developer would know for sure.

Adding npm@ who has more knowledge of the user timing code in case he has any insight.
Cc: l...@chromium.org
lpy@ might have context on the conventions used and why the parser is failing in this case.
Project Member

Comment 17 by bugdroid1@chromium.org, Oct 18

The following revision refers to this bug:
  https://chromium.googlesource.com/catapult/+/547a6910a9d92a0772a73f97a6b08f7049c3f89f

commit 547a6910a9d92a0772a73f97a6b08f7049c3f89f
Author: Emily Hanley <eyaich@google.com>
Date: Thu Oct 18 17:42:44 2018

Updating user timing argument regex to not parse on subsequent ':' chars.

In the bug this regex fails on
"measure_adobe_target_visitor_id:request:1:mbox:target-global-mbox"
From this design doc: https://docs.google.com/document/d/1-44PszmhQ0-M6Sf2dZpVu-9jAOa7w2_vKAKckRWXJms/edit# I think it is valid GroupName:TaskName the task name just
has multiple ':' chars and our regex filters them out.


Bug: chromium:892184
Change-Id: I7afef8d7c69641ae0c63f310ce0c972ba62a49ef
Reviewed-on: https://chromium-review.googlesource.com/c/1281482
Reviewed-by: lpy <lpy@chromium.org>
Commit-Queue: Emily Hanley <eyaich@chromium.org>

[modify] https://crrev.com/547a6910a9d92a0772a73f97a6b08f7049c3f89f/tracing/tracing/extras/importer/trace_event_importer.html

Project Member

Comment 18 by bugdroid1@chromium.org, Oct 18

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/496421137e4e059d0c26c953d9c63497aa0f2c53

commit 496421137e4e059d0c26c953d9c63497aa0f2c53
Author: chromium-autoroll <chromium-autoroll@skia-public.iam.gserviceaccount.com>
Date: Thu Oct 18 19:59:49 2018

Roll src/third_party/catapult 3d878160972c..1922eb00bbd9 (5 commits)

https://chromium.googlesource.com/catapult.git/+log/3d878160972c..1922eb00bbd9


git log 3d878160972c..1922eb00bbd9 --date=short --no-merges --format='%ad %ae %s'
2018-10-18 vmpstr@chromium.org Update trace categories to reflect new trace names.
2018-10-18 eyaich@google.com Updating user timing argument regex to not parse on subsequent ':' chars.
2018-10-18 benjhayden@chromium.org Add chopsui to third_party via bower.
2018-10-18 cbruni@chromium.org [results.html] Speed up <histogram-json> parsing
2018-10-18 perezju@chromium.org [pinpoint_cli] Add try job configs for v8 and scheduler teams


Created with:
  gclient setdep -r src/third_party/catapult@1922eb00bbd9

The AutoRoll server is located here: https://autoroll.skia.org/r/catapult-autoroll

Documentation for the AutoRoller is here:
https://skia.googlesource.com/buildbot/+/master/autoroll/README.md

If the roll is causing failures, please contact the current sheriff, who should
be CC'd on the roll, and stop the roller if necessary.

CQ_INCLUDE_TRYBOTS=luci.chromium.try:android_optional_gpu_tests_rel;luci.chromium.try:linux_optional_gpu_tests_rel;luci.chromium.try:mac_optional_gpu_tests_rel;luci.chromium.try:win_optional_gpu_tests_rel

BUG=chromium:892184, chromium:879526 
TBR=sullivan@chromium.org

Change-Id: I41ed30ce8eb8a704b4105398214b09008cff9566
Reviewed-on: https://chromium-review.googlesource.com/c/1289132
Reviewed-by: chromium-autoroll <chromium-autoroll@skia-public.iam.gserviceaccount.com>
Commit-Queue: chromium-autoroll <chromium-autoroll@skia-public.iam.gserviceaccount.com>
Cr-Commit-Position: refs/heads/master@{#600874}
[modify] https://crrev.com/496421137e4e059d0c26c953d9c63497aa0f2c53/DEPS

Sign in to add a comment