SyntaxError: JSON.parse: expected double-quoted property name at line 1 column 46 of the JSON data

RESOLVED FIXED in Firefox 54

Status

()

Toolkit
Telemetry
P3
normal
RESOLVED FIXED
a year ago
a year ago

People

(Reporter: Guilherme Lima, Assigned: sfink)

Tracking

Trunk
mozilla54
x86_64
Windows 7
Points:
---

Firefox Tracking Flags

(firefox53 affected, firefox54 fixed)

Details

(Whiteboard: [measurement:client])

Attachments

(1 attachment, 1 obsolete attachment)

(Reporter)

Description

a year ago
On latest Nightly, Browser Console is spammed with a lot of
SyntaxError: JSON.parse: expected double-quoted property name at line 1 column 46 of the JSON data     GCTelemetry.jsm:194:16
which points to 'let data = JSON.parse(arg);' in view-source:resource://gre/modules/GCTelemetry.jsm
Don't know when the problem appeared.
Bill, can you take a look at this?
Flags: needinfo?(wmccloskey)
Priority: -- → P3
Whiteboard: [measurement:client]
Steve, might anything have changed recently that would produce invalid JSON from the GC statistics?
Flags: needinfo?(wmccloskey) → needinfo?(sphink)
(In reply to Bill McCloskey (:billm) from comment #2)
> Steve, might anything have changed recently that would produce invalid JSON
> from the GC statistics?

Yes. I switched the GC stats to mozilla::Time{Stamp,Duration} in bug 1173354, which ended up touching lots of the formatting code. I must have mangled this. I'll take a look.
Assignee: nobody → sphink
Flags: needinfo?(sphink)
I have not been able to reproduce this. The JSON in my test is ok, and I do not see any of these message on the console.

Going on the theory that the fields are often fixed-width, column 46 looks like the value of total_time, which is total.ToMilliseconds(). I don't know what would be produced on OOM in a non-DEBUG build (see bug 1326343); I should land that, but it seems unlikely to be the culprit.

If I understood how the browser plumbing worked, perhaps I could give you a way to insert your own garbage-collection-statistics observer and dump out the value in this situation. But I don't.

Is this still happening? Do you have the pref javascript.options.mem.notify set?

I tried turning on the pref, then running the following code in Scratchpad, but got no console messages in my Nightly (successful or otherwise):

Components.utils.import('resource://gre/modules/Services.jsm');
function observer(subject, topic, json) {
    var data = JSON.parse(json);
    console.log("Parsed gc stats ok");
}
Services.obs.addObserver(observer, "garbage-collection-statistics", false);

I imagine there's a good reason why that didn't work, but I don't know enough to know what it is.
Flags: needinfo?(guijoselito)
Flags: needinfo?(wmccloskey)
(Reporter)

Comment 5

a year ago
I had 'javascript.options.mem.notify' as false. Changed it to true and ran the code, but all I got was
/*
Exception: TypeError: Components.utils is undefined
@Scratchpad/1:10:1
*/

Maybe I have to change another config beside 'javascript.options.mem.notify' to true to make the code work?
No, you're running in content mode (the default). You'd have to change to browser mode in the Environment tab. But it still doesn't work. For me, at least.
(In reply to Steve Fink [:sfink] [:s:] from comment #6)
> No, you're running in content mode (the default). You'd have to change to
> browser mode in the Environment tab. But it still doesn't work. For me, at
> least.

And to do that, you need to follow these instructions:
https://developer.mozilla.org/en-US/docs/Tools/Scratchpad#Running_Scratchpad_in_the_browser_context

Strangely, Steve's code works for me. I see "Parsed gc stats ok" in the console.
Flags: needinfo?(wmccloskey)
(Reporter)

Comment 8

a year ago
/*
Exception: SyntaxError: missing } after function body
WCA_evalWithDebugger@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webconsole.js:1366:16
WCA_onEvaluateJS@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webconsole.js:898:20
WCA_onEvaluateJSAsync@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/actors/webconsole.js:868:20
onPacket@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/main.js:1776:15
send/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/transport/transport.js:570:13
exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
exports.makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/shared/ThreadSafeDevToolsUtils.js:101:14
*/

I hope I got things right!
Flags: needinfo?(guijoselito)
That doesn't look right. I think you might have missed some of the code or something (maybe a '{').
(Reporter)

Comment 10

a year ago
With Scratchpad alerting me to "This scratchpad executes in the Browser context." pasting only the code pointed by sfink, and clicking in Display, I get:
/*
undefined
*/
That sounds better. Do you see anything in the browser console after that?
(Reporter)

Comment 12

a year ago
Just a bunch of
SyntaxError: JSON.parse: expected double-quoted property name at line 1 column 46 of the JSON data[Learn More] Scratchpad/4:12:16
which points to 'console.log("Parsed gc stats ok");'
OK, I think it's working! Unfortunately Steve's snippet doesn't give us the data we need. Can you run this in the same way?

Components.utils.import('resource://gre/modules/Services.jsm');
function observer(subject, topic, json) {
    console.log("GC JSON", json);
    var data = JSON.parse(json);
    console.log("Parsed gc stats ok");
}
Services.obs.addObserver(observer, "garbage-collection-statistics", false);

With that, we'll be able to see the JSON that's giving the error. A big string will appear in the console starting with "GC JSON". Please attach the rest to the bug.
Flags: needinfo?(guijoselito)
(Reporter)

Comment 14

a year ago
GC JSON {"timestamp":1483674960219000,"max_pause":33,120,"total_time":146,346,"zones_collected":2,"total_zones":8,"total_compartments":448,"minor_gcs":12,"store_buffer_overflows":0,"mmu_20ms":0,"mmu_50ms":33,"scc_sweep_total":5,246,"scc_sweep_max_pause":5,246,"nonincremental_reason":"None","allocated":36,"added_chunks":0,"removed_chunks":0,"slices":[{"slice":0,"pause":11,026,"when":0,000,"reason":"CC_WAITING","initial_state":"NotActive","final_state":"Mark","budget":"10ms","page_faults":52,"start_timestamp":11598,700,"end_timestamp":11598,711,"times":{"wait_background_thread":0,017,"mark_discard_code":1,037,"purge":0,070,"mark":5,610,"mark_roots":3,758,"buffer_gray_roots":2,011,"mark_cross_compartment_wrappers":0,461,"mark_c_and_js_stacks":0,001,"mark_embedding":0,103,"mark_compartments":0,954,"unmark":0,792,"minor_gcs_to_evict_nursery":2,349,"mark_roots":0,227,"mark_c_and_js_stacks":0,002}},{"slice":1,"pause":10,083,"when":49,295,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":0,"start_timestamp":11598,750,"end_timestamp":11598,760,"times":{"wait_background_thread":0,000,"mark":9,091,"minor_gcs_to_evict_nursery":0,971}},{"slice":2,"pause":10,038,"when":73,961,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":3,"start_timestamp":11598,774,"end_timestamp":11598,784,"times":{"wait_background_thread":0,000,"mark":9,775,"minor_gcs_to_evict_nursery":0,228}},{"slice":3,"pause":10,029,"when":98,869,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":1,"start_timestamp":11598,799,"end_timestamp":11598,809,"times":{"wait_background_thread":0,001,"mark":9,951,"minor_gcs_to_evict_nursery":0,056}},{"slice":4,"pause":10,031,"when":122,848,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":6,"start_timestamp":11598,823,"end_timestamp":11598,833,"times":{"wait_background_thread":0,000,"mark":9,975,"minor_gcs_to_evict_nursery":0,025}},{"slice":5,"pause":10,024,"when":146,961,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":0,"start_timestamp":11598,847,"end_timestamp":11598,857,"times":{"wait_background_thread":0,000,"mark":9,978,"minor_gcs_to_evict_nursery":0,027}},{"slice":6,"pause":10,117,"when":170,167,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":0,"start_timestamp":11598,871,"end_timestamp":11598,881,"times":{"wait_background_thread":0,001,"mark":10,073,"minor_gcs_to_evict_nursery":0,024}},{"slice":7,"pause":10,015,"when":192,776,"reason":"REFRESH_FRAME","initial_state":"Mark","final_state":"Mark","budget":"10ms","page_faults":0,"start_timestamp":11598,893,"end_timestamp":11598,903,"times":{"wait_background_thread":0,001,"mark":9,968,"minor_gcs_to_evict_nursery":0,027}},{"slice":8,"pause":33,120,"when":303,537,"reason":"INTER_SLICE_GC","initial_state":"Mark","final_state":"Mark","budget":"40ms","page_faults":0,"start_timestamp":11599,004,"end_timestamp":11599,037,"times":{"wait_background_thread":0,000,"mark":33,078,"minor_gcs_to_evict_nursery":0,024}},{"slice":9,"pause":31,729,"when":436,949,"reason":"INTER_SLICE_GC","initial_state":"Mark","final_state":"Finalize","budget":"40ms","page_faults":696,"start_timestamp":11599,137,"end_timestamp":11599,169,"times":{"wait_background_thread":0,001,"mark":0,050,"mark_delayed":0,007,"sweep":30,220,"mark_during_sweeping":5,186,"mark_incoming_black_pointers":0,011,"mark_weak":0,539,"mark_incoming_gray_pointers":0,005,"mark_gray":4,333,"mark_gray_and_weak":0,293,"finalize_start_callbacks":0,373,"per_slice_weak_callback":0,079,"per_compartment_weak_callback":0,292,"sweep_compartments":18,194,"sweep_discard_code":0,609,"sweep_cross_compartment_wrappers":1,944,"sweep_type_objects":0,145,"sweep_breakpoints":1,063,"sweep_miscellaneous":0,719,"sweep_type_information":13,501,"sweep_type_tables_and_compilations":0,001,"free_type_arena":0,007,"sweep_object":0,545,"sweep_string":0,075,"sweep_script":0,402,"sweep_scope":0,000,"sweep_shape":0,946,"sweep_jit_code":0,057,"finalize_end_callback":0,378,"deallocate":1,191,"minor_gcs_to_evict_nursery":0,524,"mark_roots":0,203,"mark_c_and_js_stacks":0,001}},{"slice":10,"pause":0,076,"when":536,336,"reason":"REFRESH_FRAME","initial_state":"Finalize","final_state":"Decommit","budget":"10ms","page_faults":1,"start_timestamp":11599,237,"end_timestamp":11599,237,"times":{"wait_background_thread":0,001,"sweep":0,017,"deallocate":0,017,"minor_gcs_to_evict_nursery":0,025}},{"slice":11,"pause":0,058,"when":637,091,"reason":"INTER_SLICE_GC","initial_state":"Decommit","final_state":"NotActive","budget":"40ms","page_faults":4,"start_timestamp":11599,338,"end_timestamp":11599,338,"times":{"wait_background_thread":0,001,"minor_gcs_to_evict_nursery":0,022}}],"totals":{"wait_background_thread":0,025,"mark_discard_code":1,037,"purge":0,070,"mark":107,551,"mark_roots":3,758,"buffer_gray_roots":2,011,"mark_cross_compartment_wrappers":0,461,"mark_c_and_js_stacks":0,001,"mark_embedding":0,103,"mark_compartments":0,954,"unmark":0,792,"mark_delayed":0,007,"sweep":30,236,"mark_during_sweeping":5,186,"mark_incoming_black_pointers":0,011,"mark_weak":0,539,"mark_incoming_gray_pointers":0,005,"mark_gray":4,333,"mark_gray_and_weak":0,293,"finalize_start_callbacks":0,373,"per_slice_weak_callback":0,079,"per_compartment_weak_callback":0,292,"sweep_compartments":18,194,"sweep_discard_code":0,609,"sweep_cross_compartment_wrappers":1,944,"sweep_type_objects":0,145,"sweep_breakpoints":1,063,"sweep_miscellaneous":0,719,"sweep_type_information":13,501,"sweep_type_tables_and_compilations":0,001,"free_type_arena":0,007,"sweep_object":0,545,"sweep_string":0,075,"sweep_script":0,402,"sweep_scope":0,000,"sweep_shape":0,946,"sweep_jit_code":0,057,"finalize_end_callback":0,378,"deallocate":1,207,"minor_gcs_to_evict_nursery":4,302,"mark_roots":0,430,"mark_c_and_js_stacks":0,004,"barriers":4,904,"unmark_gray":4,584}} Scratchpad/6:13:5
Flags: needinfo?(guijoselito)
Ah. It's the ,/. internationalization thing. So this did regress with bug 1173354. Previously we printed the decimal point ourselves.
Also, thanks Guilherme! We have everything we need now.
Duplicate of this bug: 1330901
Created attachment 8828927 [details] [diff] [review]
Fix locale-dependence in GC statistics JSON output

Revert back to using %llu.%03llu instead of %.3f. I totally forgot that that's why it was written that way. Ugh.
Attachment #8828927 - Flags: review?(jcoppeard)
Attachment #8828927 - Flags: review?(jcoppeard)
Created attachment 8828932 [details] [diff] [review]
Fix locale-dependence in GC statistics JSON output

Ok, this time reporting milliseconds.
Attachment #8828932 - Flags: review?(jcoppeard)
Attachment #8828927 - Attachment is obsolete: true
Comment on attachment 8828932 [details] [diff] [review]
Fix locale-dependence in GC statistics JSON output

Review of attachment 8828932 [details] [diff] [review]:
-----------------------------------------------------------------

Kinda gross but necessary.

Thanks for adding the comments.
Attachment #8828932 - Flags: review?(jcoppeard) → review+

Comment 21

a year ago
Pushed by sfink@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/43346af8aae0
Fix locale-dependence in GC statistics JSON output, r=jonco

Comment 22

a year ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/43346af8aae0
Status: NEW → RESOLVED
Last Resolved: a year ago
status-firefox54: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla54
You need to log in before you can comment on or make changes to this bug.