Add a trace, this trace was recorded when only gpu was enabled, and couldn't be imported by trace viewer because the json string is incomplete, and thus the format is invalid.

This situation happens randomly on my machine, especially when creating trace event with argument(for example use TRACE_EVENT2), and the dumped json string are all incomplete.

I think the reason is when we are dumping trace events to json string, something goes wrong and the dumping process is aborted. In addition to incomplete json string, I also see two trace events string overlapping each other at the end of the dumping json string.

Deleted: gpu_cannt_import.json.gz 85.3 KB

gpu_cannt_import.json.gz 85.3 KB Download

This is a very serious bug. Any update on what's going on here?

This is also blocking AboutTracingIntegrationTest.testBasicTraceRecording running on windows (https://codereview.chromium.org/2189603002/).

Log:
https://chromium-swarm.appspot.com/user/task/3045b65a1c7a8610

  Traceback (most recent call last):
    File "e:\b\swarm_slave\w\irs4_fmp\third_party\catapult\telemetry\telemetry\testing\browser_test_case.py", line 41, in WrappedMethod
      method(self)
    File "e:\b\swarm_slave\w\irs4_fmp\tools\perf\core\about_tracing_integration_test.py", line 32, in testBasicTraceRecording
      action_runner.WaitForElement(selector='div[title~="Browser"]')
    File "e:\b\swarm_slave\w\irs4_fmp\third_party\catapult\telemetry\telemetry\internal\actions\action_runner.py", line 206, in WaitForElement
      timeout_in_seconds=timeout_in_seconds))
    File "e:\b\swarm_slave\w\irs4_fmp\third_party\catapult\telemetry\telemetry\internal\actions\action_runner.py", line 45, in _RunAction
      action.RunAction(self._tab)
    File "e:\b\swarm_slave\w\irs4_fmp\third_party\catapult\telemetry\telemetry\internal\actions\wait.py", line 22, in RunAction
      wait=True, timeout_in_seconds=self.timeout_in_seconds)
    File "e:\b\swarm_slave\w\irs4_fmp\third_party\catapult\telemetry\telemetry\internal\actions\page_action.py", line 113, in EvaluateCallbackWithElement
      tab.WaitForJavaScriptExpression(code, timeout_in_seconds)
    File "e:\b\swarm_slave\w\irs4_fmp\third_party\catapult\telemetry\telemetry\internal\browser\web_contents.py", line 136, in WaitForJavaScriptExpression
      e.message + '\n' + debug_message)
  TimeoutException: Timed out while waiting 60s for IsJavaScriptExpressionTrue.
  Console output:
  (log) chrome://tracing/tracing.js:1438: SyntaxError: Unexpected end of JSON input
  (log) chrome://tracing/tracing.js:2036: Error: Could not find an importer for the provided eventData.
      at Import.createImports (chrome://tracing/tracing.js:1439:64)
      at Task.run (chrome://tracing/tracing.js:2024:13)
      at runAnother (chrome://tracing/tracing.js:2036:136)
      at runTask (chrome://tracing/tracing.js:1999:57)
      at processIdleWork (chrome://tracing/tracing.js:2005:116)
      at window.requestIdleCallback.timeout (chrome://tracing/tracing.js:1993:81)

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

commit a6c428bad618519ab8c696f697a4208022c6d9b3
Author: nednguyen <nednguyen@google.com>
Date: Wed Jul 27 16:11:28 2016

[tools/perf] Add integration test for about://tracing UI

BUG= 631812 , 631535 , 630030 

Review-Url: https://codereview.chromium.org/2189603002
Cr-Commit-Position: refs/heads/master@{#408143}

[add] https://crrev.com/a6c428bad618519ab8c696f697a4208022c6d9b3/tools/perf/core/about_tracing_integration_test.py

I am trying to repro myself on ToT but don't seem able to repro.
Also the attachment in #1 seems corrupted from a gzip viewpoint. I cannot uncompress it:
$ gunzip ~/Downloads/gpu_cannt_import.json.gz 

gzip: /usr/local/google/home/primiano/Downloads/gpu_cannt_import.json.gz: unexpected end of file


can you reupload it?

Primiano, the tracing UI test is failing on windows. Is your ToT build on windows?

primiano@ - It can not be unzipped manually, trace viewer can unzip it and get the incomplete json string.

The symptom is that the gzip'ed output from about:tracing is corrupted, truncated, or similar. The bad event seems to be causing the writing of the trace to abort.

 Issue 632238  has been merged into this issue.

This happens on Mac too.

Re #7: The bug says "(reproduced on Mac OS, Linux)"

Re #8:  "It can not be unzipped manually"? Why? All traces are just a gzip of the json file. That file looks corrupt.
I also managed to partially ungzip it, but that contains a JSON trace which is not terminated. There is no way anything can import that.
I am trying now to figure out if that is an unrelated problem or the cause here.
To be honest that would explain the "Unexpected end of JSON input".

Re #9: ok this makes sense. The only thing I can think about at the moment is that the GPU process crashes (OOM) while the trace is being finalized and stop sending the serialized JSON to the browser process. I am running out of time today but tomorrow can have a look on windows.

Re #11: does it happen on ToT?

Primiano: this happens on TOT. Since we added the integration test to CQ, it has been failing flakily & just got disabled: https://build.chromium.org/p/chromium.mac/builders/Mac10.10%20Tests/builds/7675

Please also see  Issue 632286  (probably a dupe, but has repro steps on Chrome OS).

I managed to repro on Windows ToT. This is not related with the gpu category. It happens even if I just disable all and tick only IPC. Also it is not specific with the acquarium page, it happened with theverge.com.

I start suspecting that the changes recently happening in content/browser/tracing (e.g., https://codereview.chromium.org/2152603002) might be related.
It seems that we lose JSON chunks along the way.

I'm trying to bisect and see if my speculation is right. Adding caseq in the meantime.
Agree that this is a pretty bad tracing bug.

I'll have a look -- there's pretty good chance that this is one of my recent changes.

 Issue 629530  has been merged into this issue.

 Issue 632286  has been merged into this issue.

 Issue 632796  has been merged into this issue.

I'm fairly sure that this bug is the same as https://github.com/catapult-project/catapult/issues/2529, which I suspect is related to the work with the tracing_controller_data_sink. https://chromium.googlesource.com/chromium/src/+log/master/content/browser/tracing/tracing_controller_impl_data_sinks.cc

From what I could tell, the problem was that trace viewer was receiving a JSON string that was truncated in the middle. caseq@, do you know if any of your work might be causing something like that?

Yes -- the fix is on the way: https://codereview.chromium.org/2193323002/

Thanks caseq@!

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

commit e0fd517bbea7b3dca905473b98391b6e0000056a
Author: caseq <caseq@chromium.org>
Date: Fri Jul 29 23:48:55 2016

Tracing: fix error checking from deflate() when compressing trace

Initially broken by https://codereview.chromium.org/2150783002

BUG= 629530 , 630030 

Review-Url: https://codereview.chromium.org/2193323002
Cr-Commit-Position: refs/heads/master@{#408806}

[modify] https://crrev.com/e0fd517bbea7b3dca905473b98391b6e0000056a/content/browser/tracing/tracing_controller_impl_data_sinks.cc
[modify] https://crrev.com/e0fd517bbea7b3dca905473b98391b6e0000056a/tools/perf/core/about_tracing_integration_test.py
[modify] https://crrev.com/e0fd517bbea7b3dca905473b98391b6e0000056a/tools/valgrind/gtest_exclude/browser_tests.gtest-drmemory.txt

Verified on Chrome OS 8658.0.0 / Chrome 54.0.2813.0, using steps in  Issue 632286 .

Thanks!